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/tmpmhSP8m.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpDleA85 --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/tmpx5vd7tmerge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552960825360393, "id": "8918596265545281392", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58476", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69593", "scheduler_invocation_id:9084026327520800160", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58476, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "parent_got_revision_cp": "refs/heads/master@{#641797}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "parent_got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "parent_got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27160}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "swarm_hashes": {"accessibility_unittests": "b7663b306729f0d246cc2c45453df701552cab98", "angle_unittests": "d0c24c1b00429d44b0e66f66362f295e70d8bd25", "app_shell_unittests": "3c8f9270f4554c031bd2f76627b30b90a00c3067", "aura_unittests": "e18df401d2e6e3ddf700ec92b824813e2926f83d", "base_unittests": "597993844ba3a0085baccb17549706b975b6fc42", "blink_common_unittests": "a2feddb9a4c7b14d96419aa33805aa3f9e1f38cd", "blink_fuzzer_unittests": "74ff3a19cbdf8588e1c7c3cf7fea33eb885e0aff", "blink_heap_unittests": "22834f276ae091b2805c0fa737ca8a5637fa0685", "blink_platform_unittests": "f77dfe45b6ba90bc78eb8d4e86f702607ed71911", "blink_unittests": "32f93d2157808db2ce92b2bf22ec794a57e76b12", "boringssl_crypto_tests": "dd6245609029a5ce6b2fe7c4dd0a711d90738f98", "boringssl_ssl_tests": "d5a2741c6d44a1b8f5a25ef9f3abf60ba5380675", "browser_tests": "7d1d70e85f43a47603a93781e68336313bc5d9b7", "cacheinvalidation_unittests": "92bae042efa4e707f1e9080f514af067db1848b9", "capture_unittests": "269807155e2fc4a2f3d003147664b9d0f5403d7c", "cast_unittests": "3063d13cde43b794eec0efd3083f5c0f4f9fb1df", "cc_unittests": "0e3c76904405745ff00130b39196b3d6b5ba7d4b", "chrome_app_unittests": "3a255ed41175c4be9753d27a2ee35620bbebc413", "chromedriver_unittests": "a94b005fe859e7eb288538277ffb5e8a0083fd5b", "components_browsertests": "255f881d47a90022eb5364dbc2732d16ac5a44e7", "components_unittests": "f3e25ebdfe7ab42b7f1e28c127a26096fd7f1c85", "compositor_unittests": "0df61d29ce76ad140d5b22892e32b49e0c237043", "content_browsertests": "4d724190be7e840b2708e7df42f7d730fc63218e", "content_unittests": "9669c1ab83fffdcbfee04de4ec10acf7694df2d5", "cronet_tests": "c72cec42aaeacd3b2f04b9408f8de15b9de83a62", "cronet_unittests": "07e1bfd03fa0e6314b053f0599309a7fad4c3711", "crypto_unittests": "dbf146e11fb53acf911e0fd24865f82020f83008", "dbus_unittests": "7eebafc657e9cd5b41553dba19019df1359daee3", "device_unittests": "92824c5d8114d7f2b4c18cd4e82b2d58bbdb7b49", "display_unittests": "d1b318b84834c6e483957bc076daad3105fd60ae", "events_unittests": "ef593b0e29860a54995e059afa7f2268e4260090", "extensions_browsertests": "3db65320bc0339db90be848ec7ada733cd85da66", "extensions_unittests": "22c39bac942226f71793dcb3f28887da9f1f3b93", "filesystem_service_unittests": "60b505b2a81b7a20b65d19d7de31b87f32609cf4", "gcm_unit_tests": "0feeb268aaef56dfd6119990fd577fcfdc22130e", "gfx_unittests": "b2b4ddda33c5a555e54114bea0df079f99a9aa55", "gl_tests": "f9df7365644ad807f7b11987c8e2bf8398723895", "gl_unittests": "be5ffe60c3c7960ca82ed9aaada0508b979d6337", "google_apis_unittests": "02da817d0ce539957f4f5b456c0a6d7901987b29", "gpu_unittests": "a06b163e6742d2f3814cbe3d9f059dd81b086083", "headless_browsertests": "6427d781d3497e40ea2158a0dfb71d262a44f36f", "headless_unittests": "624a81f0e0bee31ed0a1c588d710d99c280c2d29", "interactive_ui_tests": "9fd9ccf764a5cf0e52afd0d2e3c34cebbba49e66", "ipc_tests": "4d6f197a67d46c269f591818dda9333018ee5d3d", "jingle_unittests": "8e6a58c1c0d9630b5a63bf88a10da5bb0981396d", "latency_unittests": "cf14589a7b00fb7dc5d7143162e6b73fdc784b71", "leveldb_service_unittests": "338899d5219a7c53d1b8dcdb7429d548d489be84", "libjingle_xmpp_unittests": "4455d00bdbedec5d03a5ca0fb81c567e010bb872", "media_blink_unittests": "9a20bb67709f3412f02212ee992f6f66ce4c8f04", "media_service_unittests": "ebce42ae160b6cec86c60519fcf1814c99488833", "media_unittests": "adb88c06a25d33370ae48bf2a1c2a94ac7d6b9f3", "message_center_unittests": "4f36ae5487f032a6292a945fbf4883990e7bb23f", "midi_unittests": "6c28ae7045535f90ca3324a1e0b337e1cfdde15c", "mojo_core_unittests": "48f7d21a95ba17b282f4352bd3cf34fd24ae11ab", "mojo_unittests": "5db893a930262a987a3b7894d82299dd636508fb", "nacl_helper_nonsfi_unittests": "a078405317aeb2ff69aec85b8b0d41fff06731bd", "nacl_loader_unittests": "0469df00bb5798170016c5b3bc27634772a53ca5", "native_theme_unittests": "cabafa88273d5e18ce378225af94513be2926abc", "net_unittests": "b9341d304f40e5c42639eb59861d83c59a4e42c0", "pdf_unittests": "1e5701e94137aa105eff982b012333b2d34ba81f", "ppapi_unittests": "c18b79d3e09623d09b6d9c204de9948281447fe3", "printing_unittests": "6980251bc93f5b0dd85e343103027f1a3acf7d61", "remoting_unittests": "662ff8918de5aeb600888e87dfff7301ac7c8a50", "sandbox_linux_unittests": "3f45f9b49d729c1b3ae12010986bd8077d715fc6", "service_manager_unittests": "03798e7f9c84617fc95614168694c7749217bc09", "services_unittests": "b9d4d3b06905e6accb5627ca2393377ee4f428df", "shell_dialogs_unittests": "2f3b31ca61a6d16ba9c39519d5caca422f800265", "skia_unittests": "1d7fa2a11562793afa137dfc2ebae2681b2d0125", "snapshot_unittests": "c95f671222732bc82fec044006cca99e6118b0d4", "sql_unittests": "04506b73bbf42af7bdf99c04d6e49a817949c17c", "storage_unittests": "05de694a988c78732b0a78ba096e3f53e0e7e9e4", "sync_integration_tests": "85ff1dba4186a6bc20531e5aca23d5498f54d1c1", "traffic_annotation_auditor_unittests": "f85042f2c936ecd2524b029c34fc7c7626bf7877", "ui_base_unittests": "9c1b59442e56f0307a1073e17ebb87f559738f33", "ui_touch_selection_unittests": "1632794e393670370734f9ed70013334bb8de216", "unit_tests": "2d24ec9b0b42510f238e93f9adbf063960f5655a", "url_unittests": "7f919f7244dd68dec3e89c2f36d05460dd03750f", "views_unittests": "acf8a57f4bbfb7f3be497466b7bb3a6ced05d271", "viz_unittests": "b1a6202c164718f57ed00b41fc430f95624096ec", "vr_common_unittests": "386ad284015eee3ec211a43440bd6881c838e821", "vr_pixeltests": "36412ecd23e0e494238ebfa71597e494f0915191", "wm_unittests": "c87fc0f4e229af3602bc069b65eba7832c862575", "wtf_unittests": "bbccd30469140fd2b878ba2ef0872737c7ed5afa"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmpN59H6n.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/tmp9o_aU2.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/tmpmhSP8m.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpDleA85', '--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/tmpx5vd7tmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552960825360393, "id": "8918596265545281392", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58476", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69593", "scheduler_invocation_id:9084026327520800160", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58476, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "parent_got_revision_cp": "refs/heads/master@{#641797}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "parent_got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "parent_got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27160}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "swarm_hashes": {"accessibility_unittests": "b7663b306729f0d246cc2c45453df701552cab98", "angle_unittests": "d0c24c1b00429d44b0e66f66362f295e70d8bd25", "app_shell_unittests": "3c8f9270f4554c031bd2f76627b30b90a00c3067", "aura_unittests": "e18df401d2e6e3ddf700ec92b824813e2926f83d", "base_unittests": "597993844ba3a0085baccb17549706b975b6fc42", "blink_common_unittests": "a2feddb9a4c7b14d96419aa33805aa3f9e1f38cd", "blink_fuzzer_unittests": "74ff3a19cbdf8588e1c7c3cf7fea33eb885e0aff", "blink_heap_unittests": "22834f276ae091b2805c0fa737ca8a5637fa0685", "blink_platform_unittests": "f77dfe45b6ba90bc78eb8d4e86f702607ed71911", "blink_unittests": "32f93d2157808db2ce92b2bf22ec794a57e76b12", "boringssl_crypto_tests": "dd6245609029a5ce6b2fe7c4dd0a711d90738f98", "boringssl_ssl_tests": "d5a2741c6d44a1b8f5a25ef9f3abf60ba5380675", "browser_tests": "7d1d70e85f43a47603a93781e68336313bc5d9b7", "cacheinvalidation_unittests": "92bae042efa4e707f1e9080f514af067db1848b9", "capture_unittests": "269807155e2fc4a2f3d003147664b9d0f5403d7c", "cast_unittests": "3063d13cde43b794eec0efd3083f5c0f4f9fb1df", "cc_unittests": "0e3c76904405745ff00130b39196b3d6b5ba7d4b", "chrome_app_unittests": "3a255ed41175c4be9753d27a2ee35620bbebc413", "chromedriver_unittests": "a94b005fe859e7eb288538277ffb5e8a0083fd5b", "components_browsertests": "255f881d47a90022eb5364dbc2732d16ac5a44e7", "components_unittests": "f3e25ebdfe7ab42b7f1e28c127a26096fd7f1c85", "compositor_unittests": "0df61d29ce76ad140d5b22892e32b49e0c237043", "content_browsertests": "4d724190be7e840b2708e7df42f7d730fc63218e", "content_unittests": "9669c1ab83fffdcbfee04de4ec10acf7694df2d5", "cronet_tests": "c72cec42aaeacd3b2f04b9408f8de15b9de83a62", "cronet_unittests": "07e1bfd03fa0e6314b053f0599309a7fad4c3711", "crypto_unittests": "dbf146e11fb53acf911e0fd24865f82020f83008", "dbus_unittests": "7eebafc657e9cd5b41553dba19019df1359daee3", "device_unittests": "92824c5d8114d7f2b4c18cd4e82b2d58bbdb7b49", "display_unittests": "d1b318b84834c6e483957bc076daad3105fd60ae", "events_unittests": "ef593b0e29860a54995e059afa7f2268e4260090", "extensions_browsertests": "3db65320bc0339db90be848ec7ada733cd85da66", "extensions_unittests": "22c39bac942226f71793dcb3f28887da9f1f3b93", "filesystem_service_unittests": "60b505b2a81b7a20b65d19d7de31b87f32609cf4", "gcm_unit_tests": "0feeb268aaef56dfd6119990fd577fcfdc22130e", "gfx_unittests": "b2b4ddda33c5a555e54114bea0df079f99a9aa55", "gl_tests": "f9df7365644ad807f7b11987c8e2bf8398723895", "gl_unittests": "be5ffe60c3c7960ca82ed9aaada0508b979d6337", "google_apis_unittests": "02da817d0ce539957f4f5b456c0a6d7901987b29", "gpu_unittests": "a06b163e6742d2f3814cbe3d9f059dd81b086083", "headless_browsertests": "6427d781d3497e40ea2158a0dfb71d262a44f36f", "headless_unittests": "624a81f0e0bee31ed0a1c588d710d99c280c2d29", "interactive_ui_tests": "9fd9ccf764a5cf0e52afd0d2e3c34cebbba49e66", "ipc_tests": "4d6f197a67d46c269f591818dda9333018ee5d3d", "jingle_unittests": "8e6a58c1c0d9630b5a63bf88a10da5bb0981396d", "latency_unittests": "cf14589a7b00fb7dc5d7143162e6b73fdc784b71", "leveldb_service_unittests": "338899d5219a7c53d1b8dcdb7429d548d489be84", "libjingle_xmpp_unittests": "4455d00bdbedec5d03a5ca0fb81c567e010bb872", "media_blink_unittests": "9a20bb67709f3412f02212ee992f6f66ce4c8f04", "media_service_unittests": "ebce42ae160b6cec86c60519fcf1814c99488833", "media_unittests": "adb88c06a25d33370ae48bf2a1c2a94ac7d6b9f3", "message_center_unittests": "4f36ae5487f032a6292a945fbf4883990e7bb23f", "midi_unittests": "6c28ae7045535f90ca3324a1e0b337e1cfdde15c", "mojo_core_unittests": "48f7d21a95ba17b282f4352bd3cf34fd24ae11ab", "mojo_unittests": "5db893a930262a987a3b7894d82299dd636508fb", "nacl_helper_nonsfi_unittests": "a078405317aeb2ff69aec85b8b0d41fff06731bd", "nacl_loader_unittests": "0469df00bb5798170016c5b3bc27634772a53ca5", "native_theme_unittests": "cabafa88273d5e18ce378225af94513be2926abc", "net_unittests": "b9341d304f40e5c42639eb59861d83c59a4e42c0", "pdf_unittests": "1e5701e94137aa105eff982b012333b2d34ba81f", "ppapi_unittests": "c18b79d3e09623d09b6d9c204de9948281447fe3", "printing_unittests": "6980251bc93f5b0dd85e343103027f1a3acf7d61", "remoting_unittests": "662ff8918de5aeb600888e87dfff7301ac7c8a50", "sandbox_linux_unittests": "3f45f9b49d729c1b3ae12010986bd8077d715fc6", "service_manager_unittests": "03798e7f9c84617fc95614168694c7749217bc09", "services_unittests": "b9d4d3b06905e6accb5627ca2393377ee4f428df", "shell_dialogs_unittests": "2f3b31ca61a6d16ba9c39519d5caca422f800265", "skia_unittests": "1d7fa2a11562793afa137dfc2ebae2681b2d0125", "snapshot_unittests": "c95f671222732bc82fec044006cca99e6118b0d4", "sql_unittests": "04506b73bbf42af7bdf99c04d6e49a817949c17c", "storage_unittests": "05de694a988c78732b0a78ba096e3f53e0e7e9e4", "sync_integration_tests": "85ff1dba4186a6bc20531e5aca23d5498f54d1c1", "traffic_annotation_auditor_unittests": "f85042f2c936ecd2524b029c34fc7c7626bf7877", "ui_base_unittests": "9c1b59442e56f0307a1073e17ebb87f559738f33", "ui_touch_selection_unittests": "1632794e393670370734f9ed70013334bb8de216", "unit_tests": "2d24ec9b0b42510f238e93f9adbf063960f5655a", "url_unittests": "7f919f7244dd68dec3e89c2f36d05460dd03750f", "views_unittests": "acf8a57f4bbfb7f3be497466b7bb3a6ced05d271", "viz_unittests": "b1a6202c164718f57ed00b41fc430f95624096ec", "vr_common_unittests": "386ad284015eee3ec211a43440bd6881c838e821", "vr_pixeltests": "36412ecd23e0e494238ebfa71597e494f0915191", "wm_unittests": "c87fc0f4e229af3602bc069b65eba7832c862575", "wtf_unittests": "bbccd30469140fd2b878ba2ef0872737c7ed5afa"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmpN59H6n.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/tmp9o_aU2.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests',) ok_ret: frozenset([0]) step_test_data: <lambda>(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 55540 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/8918596265545281392 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itqcInzG/luci_context.601999530 MAC_CHROMIUM_TMPDIR: /b/swarming/w/ir/tmp/t METHOD: dhcp NO_GCE_CHECK: False PATH: /b/swarming/w/ir/cache/swarming_client:/b/swarming/w/ir/cipd_bin_packages:/b/swarming/w/ir/cipd_bin_packages/bin:/b/swarming/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin PWD: /b/swarming/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 ROOT_SETUP_LOG: /var/log/messages/chromebuild/root-setup.log SHLVL: 1 STARTUP_LOG: /var/log/messages/chromebuild/startup.log SWARMING_BOT_ID: swarm594-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43ac7f3153b1a311 TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TERM: linux TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t UPSTART_EVENTS: net-device-up UPSTART_INSTANCE: UPSTART_JOB: chromebuild-startup USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-03-18 19:10:07,972 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpDleA85' 2019-03-18 19:10:07,972 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpDleA85' already exists! 2019-03-18 19:10:07,972 - root: [WARNING] task_output_dir existing content: [] 2019-03-18 19:10:07,972 - 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/tmp9o_aU2.json -output-dir /b/swarming/w/ir/tmp/t/tmpDleA85 -task-summary-json /b/swarming/w/ir/tmp/t/tmpN59H6n.json [D2019-03-18T19:10:07.983053-07:00 19674 0 auth.go:1265] Minting a new token {"key":"luci_ctx/17448bbd6586b131e24757b325e942857b127d674289fed39c2ba65b832a893f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T19:10:07.983166-07:00 19674 0 luci_ctx.go:138] POST http://127.0.0.1:44963/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/17448bbd6586b131e24757b325e942857b127d674289fed39c2ba65b832a893f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T19:10:07.985423-07:00 19674 0 auth.go:1222] Token expires in 4m33.014599803s {"key":"luci_ctx/17448bbd6586b131e24757b325e942857b127d674289fed39c2ba65b832a893f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43ac81b2d0319910: exit 0 Additional test environment: ASAN_OPTIONS=symbolize=0 handle_abort=1 CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioh9Ec91/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 [19869:19869:0318/132307.425461:46918060277:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [19869:19869:0318/132307.425566:46918060376:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [19869:19869:0318/132307.425909:46918060721: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 } [19869:19869:0318/132307.425967:46918060775:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24488 with a delay 500000, Now = 210919424 [19869:19869:0318/132307.426016:46918060830:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d10 with delay 500 [19869:19869:0318/132307.426092:46918060903:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d10 [19869:19869:0318/132307.426263:46918061073:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [19869:19869:0318/132307.426291:46918061102:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) [1/28] ProtocolHandlerTest.TokenMissing (2 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [19869:19869:0318/132307.426893:46918061708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002290 with delay 0 [19869:19869:0318/132307.426934:46918061742:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002290 [19869:19869:0318/132307.426969:46918061778:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 29480 with a delay 500000, Now = 210919424 [19869:19869:0318/132307.427007:46918061825:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000022b0 with delay 500 [19869:19869:0318/132307.427096:46918061904:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000022b0 [19869:19869:0318/132307.427226:46918062035:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [19869:19869:0318/132307.427327:46918062138: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 } [19869:19869:0318/132307.427383:46918062194: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 } } [19869:19869:0318/132307.427569:46918062379: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 } } } [19869:19869:0318/132307.427855:46918062666: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 (2 ms) [2/28] ProtocolHandlerTest.InvalidOutboundMessage (2 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [19869:19869:0318/132307.428361:46918063179:INFO:protocol-handler.cc(139)] Incoming message: { } [19869:19869:0318/132307.428411:46918063220:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [19869:19869:0318/132307.428439:46918063248:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [ RUN ] RecurringTaskTest.PeriodicTask [19869:19869:0318/132307.428685:46918063498:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1566207080 with a delay 10000, Now = 0 [19869:19869:0318/132307.428718:46918063528:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002970 with delay 10 [19869:19869:0318/132307.428758:46918063575:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002970 [19869:19869:0318/132307.428793:46918063601:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [19869:19869:0318/132307.428822:46918063640:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 10000 [19869:19869:0318/132307.428882:46918063691:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002990 with delay 60 [19869:19869:0318/132307.428922:46918063732:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000002990 [19869:19869:0318/132307.428945:46918063754:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [19869:19869:0318/132307.428969:46918063776:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 70000 [19869:19869:0318/132307.428996:46918063806:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000029b0 with delay 60 [19869:19869:0318/132307.429025:46918063833:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000029b0 [19869:19869:0318/132307.429048:46918063855:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [19869:19869:0318/132307.429071:46918063878:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 130000 [19869:19869:0318/132307.429099:46918063907:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000029d0 with delay 60 [19869:19869:0318/132307.429142:46918063952:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000029d0 [19869:19869:0318/132307.429163:46918063971:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [19869:19869:0318/132307.429185:46918063995:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 190000 [19869:19869:0318/132307.429244:46918064059:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x6020000029f0 with delay 60 [19869:19869:0318/132307.429294:46918064111:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x6020000029f0 [19869:19869:0318/132307.429333:46918064145:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [19869:19869:0318/132307.429364:46918064173:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 250000 [19869:19869:0318/132307.429400:46918064212:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000002a10 with delay 60 [19869:19869:0318/132307.429431:46918064239:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000002a10 [19869:19869:0318/132307.429451:46918064259:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [19869:19869:0318/132307.429474:46918064281:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 310000 [19869:19869:0318/132307.429501:46918064312:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000002a30 with delay 60 [19869:19869:0318/132307.429533:46918064340:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000002a30 [19869:19869:0318/132307.429597:46918064410:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [19869:19869:0318/132307.429634:46918064447:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 370000 [19869:19869:0318/132307.429678:46918064491:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000002a50 with delay 60 [19869:19869:0318/132307.429720:46918064533:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000002a50 [19869:19869:0318/132307.429770:46918064588:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [4/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [19869:19869:0318/132307.431210:46918066027:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1566062696 with a delay 10000, Now = 0 [19869:19869:0318/132307.431267:46918066081:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002ad0 with delay 10 [19869:19869:0318/132307.431304:46918066112:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002ad0 [19869:19869:0318/132307.431345:46918066157:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [19869:19869:0318/132307.431387:46918066195:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 50000, Now = 10000 [19869:19869:0318/132307.431435:46918066245:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002af0 with delay 50 [19869:19869:0318/132307.431464:46918066273:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000002af0 [19869:19869:0318/132307.431488:46918066295:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [19869:19869:0318/132307.431513:46918066321:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 149000, Now = 60000 [19869:19869:0318/132307.431562:46918066371:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000002b10 with delay 149 [19869:19869:0318/132307.431591:46918066403:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000002b10 [19869:19869:0318/132307.431619:46918066428:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [19869:19869:0318/132307.431641:46918066449:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 248000, Now = 210000 [19869:19869:0318/132307.431669:46918066477:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000002b30 with delay 248 [19869:19869:0318/132307.431701:46918066509:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000002b30 [19869:19869:0318/132307.431725:46918066532:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [19869:19869:0318/132307.431757:46918066569:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 446000, Now = 460000 [19869:19869:0318/132307.431790:46918066601:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000002b50 with delay 446 [19869:19869:0318/132307.431851:46918066659:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000002b50 [19869:19869:0318/132307.431870:46918066677:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [19869:19869:0318/132307.431892:46918066700:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 842000, Now = 910000 [19869:19869:0318/132307.431924:46918066736:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000002b70 with delay 842 [19869:19869:0318/132307.431968:46918066778:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000002b70 [19869:19869:0318/132307.431998:46918066808:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [19869:19869:0318/132307.432019:46918066827:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 1040000, Now = 1760000 [19869:19869:0318/132307.432056:46918066864:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000002b90 with delay 1040 [19869:19869:0318/132307.432096:46918066904:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000002b90 [19869:19869:0318/132307.432128:46918066938:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [19869:19869:0318/132307.432162:46918066970:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 1040000, Now = 2800000 [19869:19869:0318/132307.432183:46918066991:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000002bb0 with delay 1040 [19869:19869:0318/132307.432222:46918067028:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000002bb0 [19869:19869:0318/132307.432241:46918067048:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms) [ RUN ] RecurringTaskTest.OneShotTask [19869:19869:0318/132307.433382:46918068193:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1566051432 with a delay 10000, Now = 0 [19869:19869:0318/132307.433423:46918068235:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002c30 with delay 10 [19869:19869:0318/132307.433457:46918068266:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002c30 [19869:19869:0318/132307.433479:46918068286:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [19869:19869:0318/132307.433510:46918068320:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1566051432 with a delay 10000, Now = 10000 [19869:19869:0318/132307.433572:46918068381:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002c50 with delay 10 [19869:19869:0318/132307.433600:46918068409:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000002c50 [19869:19869:0318/132307.433632:46918068444:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (1 ms) [6/28] RecurringTaskTest.OneShotTask (1 ms) [ RUN ] ThrottleTest.ThrottlingScripted [19869:19869:0318/132307.434729:46918069540:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000002cd0 with delay 920 [19869:19869:0318/132307.434781:46918069588:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002cd0 [19869:19869:0318/132307.435063:46918069873:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002cf0 with delay 45000 [19869:19869:0318/132307.435952:46918070767:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002cf0 [ OK ] ThrottleTest.ThrottlingScripted (2 ms) [7/28] ThrottleTest.ThrottlingScripted (2 ms) [ RUN ] ThrottleTest.ThrottlingStorm [19869:19869:0318/132307.436119:46918070930:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002d70 with delay 990 [19869:19869:0318/132307.436188:46918070995:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002d70 [19869:19869:0318/132307.436227:46918071036:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x602000002d90 with delay 1000 [19869:19869:0318/132307.436284:46918071092:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x602000002d90 [19869:19869:0318/132307.436308:46918071115:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x602000002db0 with delay 1000 [19869:19869:0318/132307.436357:46918071164:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x602000002db0 [19869:19869:0318/132307.436378:46918071185:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x602000002dd0 with delay 1000 [19869:19869:0318/132307.436425:46918071232:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x602000002dd0 [19869:19869:0318/132307.436444:46918071251:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002df0 with delay 1000 [19869:19869:0318/132307.436507:46918071316:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002df0 [19869:19869:0318/132307.436564:46918071374:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002e10 with delay 1000 [19869:19869:0318/132307.436616:46918071423:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002e10 [19869:19869:0318/132307.436639:46918071447:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002e30 with delay 54000 [19869:19869:0318/132307.438474:46918073287:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002e30 [19869:19869:0318/132307.438519:46918073328:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002e50 with delay 1000 [19869:19869:0318/132307.438606:46918073419:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002e50 [19869:19869:0318/132307.438640:46918073450:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002e70 with delay 1000 [19869:19869:0318/132307.438707:46918073515:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002e70 [19869:19869:0318/132307.438734:46918073543:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000002e90 with delay 1000 [19869:19869:0318/132307.438784:46918073599:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000002e90 [19869:19869:0318/132307.438833:46918073642:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000002eb0 with delay 1000 [19869:19869:0318/132307.438883:46918073693:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000002eb0 [19869:19869:0318/132307.438908:46918073716:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000002ed0 with delay 1000 [19869:19869:0318/132307.438957:46918073764:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000002ed0 [19869:19869:0318/132307.438984:46918073792:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002ef0 with delay 1000 [19869:19869:0318/132307.439064:46918073880:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002ef0 [19869:19869:0318/132307.439113:46918073924:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002f10 with delay 54000 [19869:19869:0318/132307.440832:46918075647:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002f10 [19869:19869:0318/132307.440907:46918075721:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002f30 with delay 1000 [19869:19869:0318/132307.440995:46918075804:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002f30 [19869:19869:0318/132307.441022:46918075830:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002f50 with delay 1000 [19869:19869:0318/132307.441072:46918075879:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002f50 [19869:19869:0318/132307.441091:46918075898:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002f70 with delay 1000 [19869:19869:0318/132307.441159:46918075968:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002f70 [19869:19869:0318/132307.441186:46918075994:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000002f90 with delay 1000 [19869:19869:0318/132307.441375:46918076184:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000002f90 [19869:19869:0318/132307.441401:46918076209:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000002fb0 with delay 1000 [19869:19869:0318/132307.441458:46918076265:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000002fb0 [19869:19869:0318/132307.441477:46918076284:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000002fd0 with delay 1000 [19869:19869:0318/132307.441528:46918076334:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000002fd0 [19869:19869:0318/132307.441575:46918076383:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002ff0 with delay 54000 [19869:19869:0318/132307.443229:46918078041:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002ff0 [19869:19869:0318/132307.443289:46918078100:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000003010 with delay 1000 [19869:19869:0318/132307.443347:46918078155:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000003010 [19869:19869:0318/132307.443377:46918078188:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000003030 with delay 1000 [19869:19869:0318/132307.443430:46918078237:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000003030 [19869:19869:0318/132307.443454:46918078261:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000003050 with delay 1000 [19869:19869:0318/132307.443501:46918078309:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000003050 [19869:19869:0318/132307.443521:46918078329:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000003070 with delay 1000 [19869:19869:0318/132307.443631:46918078441:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000003070 [19869:19869:0318/132307.443662:46918078473:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000003090 with delay 1000 [19869:19869:0318/132307.443714:46918078521:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000003090 [19869:19869:0318/132307.443733:46918078541:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000030b0 with delay 1000 [19869:19869:0318/132307.443781:46918078588:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000030b0 [19869:19869:0318/132307.443803:46918078612:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000030d0 with delay 54000 [19869:19869:0318/132307.445501:46918080313:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000030d0 [19869:19869:0318/132307.445577:46918080387:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x6020000030f0 with delay 1000 [19869:19869:0318/132307.445647:46918080456:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x6020000030f0 [19869:19869:0318/132307.445678:46918080487:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000003110 with delay 1000 [19869:19869:0318/132307.445727:46918080535:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000003110 [19869:19869:0318/132307.445747:46918080555:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000003130 with delay 1000 [19869:19869:0318/132307.445795:46918080602:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000003130 [19869:19869:0318/132307.445815:46918080640:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000003150 with delay 1000 [19869:19869:0318/132307.445893:46918080701:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000003150 [19869:19869:0318/132307.445917:46918080727:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000003170 with delay 1000 [19869:19869:0318/132307.445980:46918080787:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000003170 [19869:19869:0318/132307.446019:46918080829:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000003190 with delay 1000 [19869:19869:0318/132307.446071:46918080878:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000003190 [19869:19869:0318/132307.446091:46918080900:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000031b0 with delay 54000 [19869:19869:0318/132307.447746:46918082557:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000031b0 [ OK ] ThrottleTest.ThrottlingStorm (11 ms) [8/28] ThrottleTest.ThrottlingStorm (11 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [19870:19870:0318/132307.428702:46918063530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [19870:19870:0318/132307.429093:46918063905:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [19870:19870:0318/132307.429434:46918064252: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 } [19870:19870:0318/132307.429497:46918064308:INFO:recurring-task.cc(55)] [Startup] Scheduling 24488 with a delay 500000, Now = 210919424 [19870:19870:0318/132307.429535:46918064372:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 500 [19870:19870:0318/132307.429653:46918064465:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001e90 [19870:19870:0318/132307.429910:46918064730:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } } [ OK ] ProtocolHandlerTest.SendInitializeOnly (2 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (2 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [19870:19870:0318/132307.431084:46918065902:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "fake nonce" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [10/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [19870:19870:0318/132307.431524:46918066337:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ad0 with delay 0 [19870:19870:0318/132307.431613:46918066422:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002af0 with delay 0 [19870:19870:0318/132307.431653:46918066463:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b10 with delay 0 [19870:19870:0318/132307.431713:46918066525:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b30 with delay 0 [19870:19870:0318/132307.431746:46918066555:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b50 with delay 0 [19870:19870:0318/132307.431816:46918066626:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b70 with delay 0 [19870:19870:0318/132307.432151:46918066962:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002ad0 [19870:19870:0318/132307.432291:46918067101: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 } [19870:19870:0318/132307.432352:46918067162:INFO:recurring-task.cc(55)] [Send-info] Scheduling 36008 with a delay 500000, Now = 210919424 [19870:19870:0318/132307.432392:46918067202:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002d10 with delay 500 [19870:19870:0318/132307.432425:46918067234:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002af0 [19870:19870:0318/132307.432455:46918067266:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b10 [19870:19870:0318/132307.432482:46918067291:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b30 [19870:19870:0318/132307.432510:46918067318:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b50 [19870:19870:0318/132307.432575:46918067385:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b70 [19870:19870:0318/132307.432622:46918067434:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [19870:19870:0318/132307.432707:46918067518:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002d10 [19870:19870:0318/132307.432862:46918067671:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [19870:19870:0318/132307.433337:46918068147: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 (3 ms) [11/28] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [19870:19870:0318/132307.435038:46918069850:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } invalidation_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [12/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [19870:19870:0318/132307.435650:46918070465: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 } } [19870:19870:0318/132307.435726:46918070535: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" } [19870:19870:0318/132307.435830:46918070640: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 } } [19870:19870:0318/132307.435932:46918070741: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 [19870:19870:0318/132307.436452:46918071262: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 } } [19870:19870:0318/132307.436618:46918071428:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.MajorVersionMismatch (0 ms) [14/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [19870:19870:0318/132307.437090:46918071900: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 [19870:19870:0318/132307.437645:46918072464: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" } } [19870:19870:0318/132307.437721:46918072535:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004850 with delay 0 [19870:19870:0318/132307.437763:46918072577:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004850 [19870:19870:0318/132307.437852:46918072669: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 } [19870:19870:0318/132307.437919:46918072733:INFO:recurring-task.cc(55)] [Send-info] Scheduling 67112 with a delay 500000, Now = 210919424 [19870:19870:0318/132307.437966:46918072782:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004870 with delay 500 [19870:19870:0318/132307.438070:46918072886:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004870 [19870:19870:0318/132307.438118:46918072932: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 [19870:19870:0318/132307.474646:46918109463:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.ErrorMessage (0 ms) [17/28] ProtocolHandlerTest.ErrorMessage (0 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [19870:19870:0318/132307.475183:46918109993: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 [19867:19867:0318/132307.412139:46918046952:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 0 [19867:19867:0318/132307.412499:46918047312:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.412809:46918047619:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002550 with delay 0 [19867:19867:0318/132307.412849:46918047660:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002030 [19867:19867:0318/132307.412880:46918047696:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002550 [19867:19867:0318/132307.412978:46918047792:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.413065:46918047880:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0 [19867:19867:0318/132307.413114:46918047922:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002610 [19867:19867:0318/132307.413139:46918047948:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.413164:46918047972:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002650 with delay 0 [19867:19867:0318/132307.413218:46918048032:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002650 [19867:19867:0318/132307.413263:46918048076:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.413310:46918048118:INFO:recurring-task.cc(55)] [Startup] Scheduling 24744 with a delay 0, Now = 210919424 [19867:19867:0318/132307.413340:46918048149:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002670 with delay 0 [19867:19867:0318/132307.413370:46918048181:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002670 [19867:19867:0318/132307.413493:46918048300:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6805010003660280951" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.413523:46918048332:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 25000 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.413592:46918048404:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002690 with delay 500 [19867:19867:0318/132307.413627:46918048436:INFO:recurring-task.cc(55)] [Retry] Scheduling 24744 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.413654:46918048462:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000026b0 with delay 60000 [19867:19867:0318/132307.413740:46918048549:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002690 [19867:19867:0318/132307.413770:46918048583:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.413880:46918048690:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.414041:46918048856: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: "-6805010003660280951" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.414281:46918049090:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002750 with delay 0 [19867:19867:0318/132307.414326:46918049135:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002750 [19867:19867:0318/132307.414510:46918049318:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6805010003660280951" 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" } } [19867:19867:0318/132307.414625:46918049437:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6805010003660280951" [19867:19867:0318/132307.414670:46918049479:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.414706:46918049526:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13448 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.414755:46918049564:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002770 with delay 1200000 [19867:19867:0318/132307.414798:46918049607:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.414952:46918049760:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.415000:46918049810:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 9672 with a delay 0, Now = 211419424 [19867:19867:0318/132307.415025:46918049833:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002990 with delay 0 [19867:19867:0318/132307.415105:46918049913: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 [19867:19867:0318/132307.415139:46918049948:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002990 [19867:19867:0318/132307.415220:46918050031:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a50 with delay 0 [19867:19867:0318/132307.415257:46918050065:INFO:recurring-task.cc(55)] [Retry] Scheduling 9672 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.415285:46918050092:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a90 with delay 10000 [19867:19867:0318/132307.415307:46918050114:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002a50 [19867:19867:0318/132307.415344:46918050152:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (4 ms) [19/28] InvalidationClientImplTest.Start (4 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [19867:19867:0318/132307.416120:46918050930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000032f0 with delay 0 [19867:19867:0318/132307.416184:46918050993: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 [19867:19867:0318/132307.416670:46918051485:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 0 [19867:19867:0318/132307.416740:46918051556:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.417022:46918051832:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000041f0 with delay 0 [19867:19867:0318/132307.417061:46918051870:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b90 [19867:19867:0318/132307.417092:46918051900:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000041f0 [19867:19867:0318/132307.417142:46918051952:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.417230:46918052047:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042b0 with delay 0 [19867:19867:0318/132307.417299:46918052108:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042b0 [19867:19867:0318/132307.417324:46918052133:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.417357:46918052165:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042f0 with delay 0 [19867:19867:0318/132307.417393:46918052205:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042f0 [19867:19867:0318/132307.417423:46918052231:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.417469:46918052277:INFO:recurring-task.cc(55)] [Startup] Scheduling 48680 with a delay 0, Now = 210919424 [19867:19867:0318/132307.417496:46918052306:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004310 with delay 0 [19867:19867:0318/132307.417523:46918052330:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004310 [19867:19867:0318/132307.417606:46918052414:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1342756700922908097" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.417649:46918052458:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 48936 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.417680:46918052489:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004330 with delay 500 [19867:19867:0318/132307.417714:46918052523:INFO:recurring-task.cc(55)] [Retry] Scheduling 48680 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.417750:46918052562:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004350 with delay 60000 [19867:19867:0318/132307.417841:46918052650:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004330 [19867:19867:0318/132307.417870:46918052687:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.417921:46918052730:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.418056:46918052865: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: "1342756700922908097" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.418160:46918052971:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000043f0 with delay 0 [19867:19867:0318/132307.418187:46918052996:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000043f0 [19867:19867:0318/132307.418290:46918053101:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1342756700922908097" 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" } } [19867:19867:0318/132307.418345:46918053153:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1342756700922908097" [19867:19867:0318/132307.418375:46918053183:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.418405:46918053214:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15736 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.418432:46918053240:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004410 with delay 1200000 [19867:19867:0318/132307.418467:46918053275:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.418649:46918053464:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.418702:46918053529:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 14088 with a delay 0, Now = 211419424 [19867:19867:0318/132307.418767:46918053583:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004630 with delay 0 [19867:19867:0318/132307.418837:46918053648: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 [19867:19867:0318/132307.418892:46918053701:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004630 [19867:19867:0318/132307.418964:46918053774:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000046f0 with delay 0 [19867:19867:0318/132307.419007:46918053815:INFO:recurring-task.cc(55)] [Retry] Scheduling 14088 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.419039:46918053849:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004730 with delay 10000 [19867:19867:0318/132307.419065:46918053873:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000046f0 [19867:19867:0318/132307.419085:46918053903:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.419174:46918053984:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004750 with delay 0 [19867:19867:0318/132307.419229:46918054037:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000004750 [19867:19867:0318/132307.419266:46918054076:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [19867:19867:0318/132307.419304:46918054112:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [19867:19867:0318/132307.419332:46918054140:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [19867:19867:0318/132307.419405:46918054214:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 48936 with a delay 500000, Now = 211469424 [19867:19867:0318/132307.419434:46918054243:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004770 with delay 500 [19867:19867:0318/132307.419472:46918054281:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 48808 with a delay 60000000, Now = 211469424 [19867:19867:0318/132307.419502:46918054311:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004790 with delay 60000 [19867:19867:0318/132307.419601:46918054410:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004770 [19867:19867:0318/132307.419628:46918054439:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.419675:46918054484:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.419699:46918054506:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [19867:19867:0318/132307.419855:46918054664: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 } } } [19867:19867:0318/132307.419991:46918054803:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.420071:46918054880:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000004830 with delay 0 [19867:19867:0318/132307.420102:46918054910:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004830 [19867:19867:0318/132307.420291:46918055100: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 } } } } [19867:19867:0318/132307.420380:46918055191: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 [19867:19867:0318/132307.420448:46918055255:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [19867:19867:0318/132307.420566:46918055375:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [19867:19867:0318/132307.420644:46918055453:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [19867:19867:0318/132307.421082:46918055894:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000004730 [ OK ] InvalidationClientImplTest.Register (6 ms) [21/28] InvalidationClientImplTest.Register (6 ms) [ RUN ] InvalidationClientImplTest.Invalidations [19867:19867:0318/132307.422683:46918057496:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005410 with delay 0 [19867:19867:0318/132307.422742:46918057550:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.423077:46918057888:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005af0 with delay 0 [19867:19867:0318/132307.423112:46918057939:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005410 [19867:19867:0318/132307.423163:46918057972:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005af0 [19867:19867:0318/132307.423216:46918058026:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.423266:46918058075:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bb0 with delay 0 [19867:19867:0318/132307.423299:46918058108:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bb0 [19867:19867:0318/132307.423320:46918058127:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.423348:46918058156:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bf0 with delay 0 [19867:19867:0318/132307.423374:46918058183:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bf0 [19867:19867:0318/132307.423395:46918058203:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.423426:46918058237:INFO:recurring-task.cc(55)] [Startup] Scheduling 79784 with a delay 0, Now = 210919424 [19867:19867:0318/132307.423467:46918058276:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c10 with delay 0 [19867:19867:0318/132307.423497:46918058304:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005c10 [19867:19867:0318/132307.423584:46918058392:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3130798615300504045" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.423616:46918058426:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 80040 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.423644:46918058453:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c30 with delay 500 [19867:19867:0318/132307.423673:46918058481:INFO:recurring-task.cc(55)] [Retry] Scheduling 79784 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.423697:46918058508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c50 with delay 60000 [19867:19867:0318/132307.423742:46918058550:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005c30 [19867:19867:0318/132307.423769:46918058577:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.423807:46918058615:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.423915:46918058723: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: "-3130798615300504045" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.424000:46918058808:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005cf0 with delay 0 [19867:19867:0318/132307.424024:46918058833:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005cf0 [19867:19867:0318/132307.424151:46918058961:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3130798615300504045" 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" } } [19867:19867:0318/132307.424213:46918059024:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3130798615300504045" [19867:19867:0318/132307.424253:46918059062:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.424282:46918059090:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20840 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.424308:46918059117:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005d10 with delay 1200000 [19867:19867:0318/132307.424337:46918059146:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.424465:46918059275:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.424505:46918059315:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 20808 with a delay 0, Now = 211419424 [19867:19867:0318/132307.424532:46918059366:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005f30 with delay 0 [19867:19867:0318/132307.424613:46918059421: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 [19867:19867:0318/132307.424670:46918059478:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005f30 [19867:19867:0318/132307.424740:46918059550:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005ff0 with delay 0 [19867:19867:0318/132307.424788:46918059598:INFO:recurring-task.cc(55)] [Retry] Scheduling 20808 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.424826:46918059635:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006030 with delay 10000 [19867:19867:0318/132307.424851:46918059659:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005ff0 [19867:19867:0318/132307.424873:46918059681:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.424921:46918059732:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.424979:46918059788:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006050 with delay 0 [19867:19867:0318/132307.425007:46918059820:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006050 [19867:19867:0318/132307.425189:46918059999: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 } } } [19867:19867:0318/132307.425323:46918060132: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 [19867:19867:0318/132307.425395:46918060203: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" } [19867:19867:0318/132307.425490:46918060298:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [19867:19867:0318/132307.425585:46918060398:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [19867:19867:0318/132307.425689:46918060502:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006430 with delay 0 [19867:19867:0318/132307.425739:46918060553:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006450 with delay 0 [19867:19867:0318/132307.425780:46918060595:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006470 with delay 0 [19867:19867:0318/132307.425833:46918060647:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006430 [19867:19867:0318/132307.425904:46918060717:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 80040 with a delay 500000, Now = 211519424 [19867:19867:0318/132307.425950:46918060767:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006490 with delay 500 [19867:19867:0318/132307.426008:46918060821:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006450 [19867:19867:0318/132307.426054:46918060866:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006470 [19867:19867:0318/132307.426117:46918060930:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x602000006490 [19867:19867:0318/132307.426160:46918060974:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.426225:46918061040:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.426260:46918061070:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [19867:19867:0318/132307.426418:46918061228: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 (4 ms) [22/28] InvalidationClientImplTest.Invalidations (4 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [19867:19867:0318/132307.427109:46918061919:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006d70 with delay 0 [19867:19867:0318/132307.427171:46918061985:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.427415:46918062225:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0 [19867:19867:0318/132307.427449:46918062258:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006d70 [19867:19867:0318/132307.427474:46918062281:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290 [19867:19867:0318/132307.427533:46918062375:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.427628:46918062438:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007350 with delay 0 [19867:19867:0318/132307.427663:46918062472:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007350 [19867:19867:0318/132307.427688:46918062495:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.427738:46918062549:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007390 with delay 0 [19867:19867:0318/132307.427776:46918062585:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007390 [19867:19867:0318/132307.427801:46918062609:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.427838:46918062646:INFO:recurring-task.cc(55)] [Startup] Scheduling 109480 with a delay 0, Now = 210919424 [19867:19867:0318/132307.427866:46918062674:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073b0 with delay 0 [19867:19867:0318/132307.427892:46918062700:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000073b0 [19867:19867:0318/132307.427960:46918062770:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2245795308147681999" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.427997:46918062806:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 109736 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.428026:46918062837:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073d0 with delay 500 [19867:19867:0318/132307.428052:46918062869:INFO:recurring-task.cc(55)] [Retry] Scheduling 109480 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.428098:46918062906:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073f0 with delay 60000 [19867:19867:0318/132307.428154:46918062965:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000073d0 [19867:19867:0318/132307.428183:46918062991:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.428221:46918063030:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.428330:46918063141: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: "2245795308147681999" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.428442:46918063251:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007490 with delay 0 [19867:19867:0318/132307.428474:46918063284:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007490 [19867:19867:0318/132307.428598:46918063408:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2245795308147681999" 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" } } [19867:19867:0318/132307.428653:46918063461:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2245795308147681999" [19867:19867:0318/132307.428681:46918063491:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.428733:46918063542:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 24888 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.428787:46918063602:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000074b0 with delay 1200000 [19867:19867:0318/132307.428834:46918063646:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.428976:46918063786:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.429015:46918063824:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 26952 with a delay 0, Now = 211419424 [19867:19867:0318/132307.429045:46918063855:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076d0 with delay 0 [19867:19867:0318/132307.429095:46918063905: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 [19867:19867:0318/132307.429132:46918063941:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000076d0 [19867:19867:0318/132307.429190:46918063999:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007790 with delay 0 [19867:19867:0318/132307.429271:46918064089:INFO:recurring-task.cc(55)] [Retry] Scheduling 26952 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.429323:46918064131:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000077d0 with delay 10000 [19867:19867:0318/132307.429354:46918064162:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007790 [19867:19867:0318/132307.429375:46918064183:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.429428:46918064237:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.429470:46918064279:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000077f0 with delay 0 [19867:19867:0318/132307.429497:46918064305:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000077f0 [19867:19867:0318/132307.429638:46918064447: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 } } [19867:19867:0318/132307.429707:46918064524: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 [19867:19867:0318/132307.429749:46918064558:INFO:protocol-handler.cc(294)] Adding subtree: { } [19867:19867:0318/132307.429781:46918064589:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 109736 with a delay 500000, Now = 211469424 [19867:19867:0318/132307.429810:46918064620:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007810 with delay 500 [19867:19867:0318/132307.429837:46918064645:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [19867:19867:0318/132307.430033:46918064842: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 } [19867:19867:0318/132307.430111:46918064919:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007810 [19867:19867:0318/132307.430139:46918064949:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.430200:46918065010:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.430252:46918065061:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [19867:19867:0318/132307.430576:46918065386: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 } } [19867:19867:0318/132307.430929:46918065739:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000077d0 [ OK ] InvalidationClientImplTest.ServerRequests (6 ms) [23/28] InvalidationClientImplTest.ServerRequests (6 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [19867:19867:0318/132307.432503:46918067314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000080f0 with delay 0 [19867:19867:0318/132307.432577:46918067385:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.432815:46918067624:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000086b0 with delay 0 [19867:19867:0318/132307.432847:46918067656:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000080f0 [19867:19867:0318/132307.432875:46918067683:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000086b0 [19867:19867:0318/132307.432926:46918067734:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.432970:46918067779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008770 with delay 0 [19867:19867:0318/132307.433011:46918067819:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008770 [19867:19867:0318/132307.433032:46918067839:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.433064:46918067873:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0 [19867:19867:0318/132307.433091:46918067899:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0 [19867:19867:0318/132307.433112:46918067920:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.433138:46918067946:INFO:recurring-task.cc(55)] [Startup] Scheduling 136744 with a delay 0, Now = 210919424 [19867:19867:0318/132307.433168:46918067977:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087d0 with delay 0 [19867:19867:0318/132307.433193:46918068020:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087d0 [19867:19867:0318/132307.433301:46918068111:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3419845418933118192" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.433336:46918068145:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 137000 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.433363:46918068172:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087f0 with delay 500 [19867:19867:0318/132307.433391:46918068199:INFO:recurring-task.cc(55)] [Retry] Scheduling 136744 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.433416:46918068224:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008810 with delay 60000 [19867:19867:0318/132307.433453:46918068261:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000087f0 [19867:19867:0318/132307.433476:46918068285:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.433526:46918068336:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.433704:46918068524: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: "-3419845418933118192" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.433834:46918068648:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088b0 with delay 0 [19867:19867:0318/132307.433873:46918068687:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000088b0 [19867:19867:0318/132307.434016:46918068830:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3419845418933118192" 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" } } [19867:19867:0318/132307.434088:46918068902:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3419845418933118192" [19867:19867:0318/132307.434128:46918068941:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.434173:46918068987:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28408 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.434216:46918069025:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088d0 with delay 1200000 [19867:19867:0318/132307.434257:46918069066:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.434366:46918069174:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.434393:46918069202:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 32328 with a delay 0, Now = 211419424 [19867:19867:0318/132307.434420:46918069228:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008af0 with delay 0 [19867:19867:0318/132307.434461:46918069269: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 [19867:19867:0318/132307.434504:46918069314:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008af0 [19867:19867:0318/132307.434601:46918069410:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bb0 with delay 0 [19867:19867:0318/132307.434637:46918069445:INFO:recurring-task.cc(55)] [Retry] Scheduling 32328 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.434661:46918069472:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bf0 with delay 10000 [19867:19867:0318/132307.434686:46918069495:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008bb0 [19867:19867:0318/132307.434707:46918069522:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.434757:46918069567:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.434797:46918069606:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000008c10 with delay 0 [19867:19867:0318/132307.434832:46918069640:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000008c10 [19867:19867:0318/132307.434926:46918069735: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" } } [19867:19867:0318/132307.434994:46918069803: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 [19867:19867:0318/132307.435063:46918069871:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [19867:19867:0318/132307.435360:46918070170:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000008bf0 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [19867:19867:0318/132307.436813:46918071623:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009570 with delay 0 [19867:19867:0318/132307.436872:46918071680:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.437121:46918071930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009bf0 with delay 0 [19867:19867:0318/132307.437151:46918071960:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009570 [19867:19867:0318/132307.437182:46918071991:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009bf0 [19867:19867:0318/132307.437277:46918072089:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.437344:46918072153:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cb0 with delay 0 [19867:19867:0318/132307.437377:46918072185:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cb0 [19867:19867:0318/132307.437409:46918072217:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.437450:46918072258:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cf0 with delay 0 [19867:19867:0318/132307.437476:46918072290:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cf0 [19867:19867:0318/132307.437505:46918072314:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.437534:46918072368:INFO:recurring-task.cc(55)] [Startup] Scheduling 159400 with a delay 0, Now = 210919424 [19867:19867:0318/132307.437588:46918072398:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d10 with delay 0 [19867:19867:0318/132307.437615:46918072423:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009d10 [19867:19867:0318/132307.437691:46918072500:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "6115535642281850032" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.437734:46918072543:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 159656 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.437764:46918072572:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d30 with delay 500 [19867:19867:0318/132307.437787:46918072596:INFO:recurring-task.cc(55)] [Retry] Scheduling 159400 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.437814:46918072622:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d50 with delay 60000 [19867:19867:0318/132307.437857:46918072666:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009d30 [19867:19867:0318/132307.437885:46918072692:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.437931:46918072740:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.438073:46918072882: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: "6115535642281850032" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.438205:46918073017:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009df0 with delay 0 [19867:19867:0318/132307.438242:46918073051:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009df0 [19867:19867:0318/132307.438353:46918073162:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "6115535642281850032" 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" } } [19867:19867:0318/132307.438398:46918073210:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "6115535642281850032" [19867:19867:0318/132307.438432:46918073241:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.438465:46918073274:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31576 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.438493:46918073302:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009e10 with delay 1200000 [19867:19867:0318/132307.438522:46918073331:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.438696:46918073509:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.438740:46918073550:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 35976 with a delay 0, Now = 211419424 [19867:19867:0318/132307.438769:46918073578:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a030 with delay 0 [19867:19867:0318/132307.438812:46918073621: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 [19867:19867:0318/132307.438848:46918073657:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a030 [19867:19867:0318/132307.438905:46918073714:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a0f0 with delay 0 [19867:19867:0318/132307.438939:46918073748:INFO:recurring-task.cc(55)] [Retry] Scheduling 35976 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.438963:46918073772:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a130 with delay 10000 [19867:19867:0318/132307.439001:46918073809:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a0f0 [19867:19867:0318/132307.439035:46918073844:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.439077:46918073886:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a150 with delay 0 [19867:19867:0318/132307.439104:46918073913:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000a150 [19867:19867:0318/132307.439142:46918073951:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [19867:19867:0318/132307.439201:46918074010:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 159656 with a delay 500000, Now = 211469424 [19867:19867:0318/132307.439231:46918074041:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a170 with delay 500 [19867:19867:0318/132307.439264:46918074073:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 159528 with a delay 60000000, Now = 211469424 [19867:19867:0318/132307.439291:46918074100:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a190 with delay 60000 [19867:19867:0318/132307.439341:46918074149:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a170 [19867:19867:0318/132307.439363:46918074170:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.439405:46918074214:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.439428:46918074236:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [19867:19867:0318/132307.439575:46918074385: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 } } } [19867:19867:0318/132307.439655:46918074464:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.439697:46918074508:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000a230 with delay 0 [19867:19867:0318/132307.439746:46918074559:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a230 [19867:19867:0318/132307.439868:46918074677: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" } } [19867:19867:0318/132307.439946:46918074755: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 [19867:19867:0318/132307.439973:46918074782:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [19867:19867:0318/132307.440060:46918074868:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [19867:19867:0318/132307.440396:46918075206:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000a130 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [19867:19867:0318/132307.441993:46918076808:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ac90 with delay 0 [19867:19867:0318/132307.442069:46918076881:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.442324:46918077135:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b1b0 with delay 0 [19867:19867:0318/132307.442360:46918077168:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ac90 [19867:19867:0318/132307.442385:46918077193:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b1b0 [19867:19867:0318/132307.442438:46918077246:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.442483:46918077294:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b270 with delay 0 [19867:19867:0318/132307.442516:46918077324:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b270 [19867:19867:0318/132307.442584:46918077393:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.442625:46918077434:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2b0 with delay 0 [19867:19867:0318/132307.442653:46918077463:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2b0 [19867:19867:0318/132307.442676:46918077484:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.442705:46918077520:INFO:recurring-task.cc(55)] [Startup] Scheduling 187816 with a delay 0, Now = 210919424 [19867:19867:0318/132307.442742:46918077552:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2d0 with delay 0 [19867:19867:0318/132307.442767:46918077575:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2d0 [19867:19867:0318/132307.442819:46918077628:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3996065693176108506" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.442850:46918077658:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 188072 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.442884:46918077696:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2f0 with delay 500 [19867:19867:0318/132307.442922:46918077735:INFO:recurring-task.cc(55)] [Retry] Scheduling 187816 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.442974:46918077788:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b310 with delay 60000 [19867:19867:0318/132307.443027:46918077835:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b2f0 [19867:19867:0318/132307.443050:46918077858:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.443087:46918077899:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.443225:46918078044: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: "-3996065693176108506" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.443337:46918078145:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3b0 with delay 0 [19867:19867:0318/132307.443365:46918078174:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b3b0 [19867:19867:0318/132307.443464:46918078272:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3996065693176108506" 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" } } [19867:19867:0318/132307.443515:46918078324:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3996065693176108506" [19867:19867:0318/132307.443576:46918078389:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.443624:46918078436:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 34920 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.443670:46918078483:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3d0 with delay 1200000 [19867:19867:0318/132307.443719:46918078533:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.443902:46918078718:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.443956:46918078769:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 41352 with a delay 0, Now = 211419424 [19867:19867:0318/132307.443999:46918078813:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b5f0 with delay 0 [19867:19867:0318/132307.444064:46918078878: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 [19867:19867:0318/132307.444115:46918078928:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b5f0 [19867:19867:0318/132307.444197:46918079012:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6b0 with delay 0 [19867:19867:0318/132307.444238:46918079046:INFO:recurring-task.cc(55)] [Retry] Scheduling 41352 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.444262:46918079070:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6f0 with delay 10000 [19867:19867:0318/132307.444285:46918079092:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b6b0 [19867:19867:0318/132307.444305:46918079112:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.444350:46918079159:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b710 with delay 0 [19867:19867:0318/132307.444381:46918079212:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000b710 [19867:19867:0318/132307.444476:46918079291:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [19867:19867:0318/132307.444561:46918079372:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 188072 with a delay 500000, Now = 211469424 [19867:19867:0318/132307.444609:46918079419:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b730 with delay 500 [19867:19867:0318/132307.444638:46918079445:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 187944 with a delay 60000000, Now = 211469424 [19867:19867:0318/132307.444664:46918079473:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b750 with delay 60000 [19867:19867:0318/132307.444722:46918079530:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000b730 [19867:19867:0318/132307.444747:46918079567:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.444808:46918079617:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.444832:46918079640:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [19867:19867:0318/132307.444946:46918079755: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 } } } [19867:19867:0318/132307.445276:46918080085:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000b6f0 [19867:19867:0318/132307.446274:46918081085:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000b310 [19867:19867:0318/132307.446335:46918081143:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000b750 [19867:19867:0318/132307.446392:46918081201: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 [19867:19867:0318/132307.446425:46918081234:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [19867:19867:0318/132307.446491:46918081299: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 } [19867:19867:0318/132307.446523:46918081333:INFO:recurring-task.cc(55)] [Send-info] Scheduling 188072 with a delay 500000, Now = 271469424 [19867:19867:0318/132307.446586:46918081395:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b7f0 with delay 500 [19867:19867:0318/132307.446612:46918081420:INFO:recurring-task.cc(55)] [Retry] Scheduling 187944 with a delay 60000000, Now = 271469424 [19867:19867:0318/132307.446642:46918081451:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b810 with delay 60000 [19867:19867:0318/132307.446679:46918081487:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000b7f0 [19867:19867:0318/132307.446704:46918081548:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.446790:46918081599:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.446814:46918081622:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [19867:19867:0318/132307.446959:46918081768: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 (7 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (7 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [19867:19867:0318/132307.448535:46918083373:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c0f0 with delay 0 [19867:19867:0318/132307.448619:46918083429:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.448831:46918083641:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c610 with delay 0 [19867:19867:0318/132307.448868:46918083676:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c0f0 [19867:19867:0318/132307.448895:46918083705:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c610 [19867:19867:0318/132307.448944:46918083752:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.448991:46918083799:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6d0 with delay 0 [19867:19867:0318/132307.449031:46918083840:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6d0 [19867:19867:0318/132307.449053:46918083861:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.449080:46918083889:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c710 with delay 0 [19867:19867:0318/132307.449103:46918083911:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c710 [19867:19867:0318/132307.449122:46918083929:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.449153:46918083962:INFO:recurring-task.cc(55)] [Startup] Scheduling 216744 with a delay 0, Now = 210919424 [19867:19867:0318/132307.449177:46918083986:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c730 with delay 0 [19867:19867:0318/132307.449229:46918084037:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c730 [19867:19867:0318/132307.449301:46918084110:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3726275505793753860" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.449333:46918084143:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 217000 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.449360:46918084168:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c750 with delay 500 [19867:19867:0318/132307.449413:46918084222:INFO:recurring-task.cc(55)] [Retry] Scheduling 216744 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.449442:46918084251:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c770 with delay 60000 [19867:19867:0318/132307.449476:46918084283:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c750 [19867:19867:0318/132307.449501:46918084310:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.449538:46918084370:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.449683:46918084493: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: "3726275505793753860" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.449791:46918084600:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c810 with delay 0 [19867:19867:0318/132307.449819:46918084634:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c810 [19867:19867:0318/132307.449959:46918084769:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3726275505793753860" 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" } } [19867:19867:0318/132307.450008:46918084817:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3726275505793753860" [19867:19867:0318/132307.450037:46918084846:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.450064:46918084875:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 37560 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.450092:46918084901:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c830 with delay 1200000 [19867:19867:0318/132307.450123:46918084934:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.450243:46918085053:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.450281:46918085089:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 47304 with a delay 0, Now = 211419424 [19867:19867:0318/132307.450306:46918085114:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ca50 with delay 0 [19867:19867:0318/132307.450348:46918085155: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 [19867:19867:0318/132307.450394:46918085204:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ca50 [19867:19867:0318/132307.450450:46918085259:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb10 with delay 0 [19867:19867:0318/132307.450484:46918085294:INFO:recurring-task.cc(55)] [Retry] Scheduling 47304 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.450511:46918085321:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb50 with delay 10000 [19867:19867:0318/132307.450535:46918085368:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cb10 [19867:19867:0318/132307.450591:46918085402:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.450634:46918085443:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.450670:46918085479:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000cb70 with delay 0 [19867:19867:0318/132307.450706:46918085522:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000cb70 [19867:19867:0318/132307.450782:46918085591: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" } } [19867:19867:0318/132307.451043:46918085853:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000cb50 [19867:19867:0318/132307.451914:46918086725: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 [19867:19867:0318/132307.452598:46918087410:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0 [19867:19867:0318/132307.452655:46918087464:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [19867:19867:0318/132307.452846:46918087662:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d8f0 with delay 0 [19867:19867:0318/132307.452910:46918087720:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0 [19867:19867:0318/132307.452937:46918087745:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d8f0 [19867:19867:0318/132307.452996:46918087806:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [19867:19867:0318/132307.453042:46918087851:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9b0 with delay 0 [19867:19867:0318/132307.453073:46918087882:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9b0 [19867:19867:0318/132307.453094:46918087902:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [19867:19867:0318/132307.453120:46918087929:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9f0 with delay 0 [19867:19867:0318/132307.453145:46918087952:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9f0 [19867:19867:0318/132307.453164:46918087972:INFO:invalidation-client-core.cc(351)] Starting with no previous state [19867:19867:0318/132307.453194:46918088023:INFO:recurring-task.cc(55)] [Startup] Scheduling 238376 with a delay 0, Now = 210919424 [19867:19867:0318/132307.453248:46918088056:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da10 with delay 0 [19867:19867:0318/132307.453271:46918088079:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000da10 [19867:19867:0318/132307.453337:46918088145:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "982264618349404065" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [19867:19867:0318/132307.453367:46918088176:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 238632 with a delay 500000, Now = 210919424 [19867:19867:0318/132307.453409:46918088218:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da30 with delay 500 [19867:19867:0318/132307.453434:46918088243:INFO:recurring-task.cc(55)] [Retry] Scheduling 238376 with a delay 60000000, Now = 210919424 [19867:19867:0318/132307.453460:46918088269:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da50 with delay 60000 [19867:19867:0318/132307.453505:46918088316:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000da30 [19867:19867:0318/132307.453532:46918088340:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.453597:46918088405:INFO:invalidation-client-core.cc(488)] Return client token = "" [19867:19867:0318/132307.453707:46918088523: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: "982264618349404065" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [19867:19867:0318/132307.453820:46918088629:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000daf0 with delay 0 [19867:19867:0318/132307.453847:46918088656:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000daf0 [19867:19867:0318/132307.453966:46918088776:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "982264618349404065" 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" } } [19867:19867:0318/132307.454014:46918088822:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "982264618349404065" [19867:19867:0318/132307.454043:46918088852:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [19867:19867:0318/132307.454074:46918088883:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 40024 with a delay 1200000000, Now = 211419424 [19867:19867:0318/132307.454102:46918088921:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000db10 with delay 1200000 [19867:19867:0318/132307.454151:46918088960:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [19867:19867:0318/132307.454267:46918089077:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.454299:46918089108:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 67272 with a delay 0, Now = 211419424 [19867:19867:0318/132307.454325:46918089134:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000dd30 with delay 0 [19867:19867:0318/132307.454369:46918089177: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 [19867:19867:0318/132307.454402:46918089210:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000dd30 [19867:19867:0318/132307.454464:46918089273:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ddf0 with delay 0 [19867:19867:0318/132307.454502:46918089313:INFO:recurring-task.cc(55)] [Retry] Scheduling 67272 with a delay 10000000, Now = 211419424 [19867:19867:0318/132307.454582:46918089391:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000de30 with delay 10000 [19867:19867:0318/132307.454612:46918089420:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ddf0 [19867:19867:0318/132307.454634:46918089443:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [19867:19867:0318/132307.454917:46918089725:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000de30 [19867:19867:0318/132307.455874:46918090684:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000da50 [19867:19867:0318/132307.476068:46918110882:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000db10 [19867:19867:0318/132307.476182:46918110992:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.476239:46918111048:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [19867:19867:0318/132307.476277:46918111087:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [19867:19867:0318/132307.476464:46918111274: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 } [19867:19867:0318/132307.476532:46918111374:INFO:recurring-task.cc(55)] [Send-info] Scheduling 238632 with a delay 500000, Now = 1411419424 [19867:19867:0318/132307.476601:46918111410:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de50 with delay 500 [19867:19867:0318/132307.476652:46918111462:INFO:recurring-task.cc(55)] [Retry] Scheduling 40024 with a delay 1200000000, Now = 1411419424 [19867:19867:0318/132307.476683:46918111493:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de70 with delay 1200000 [19867:19867:0318/132307.476737:46918111545:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000de50 [19867:19867:0318/132307.476762:46918111571:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.476830:46918111641:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [19867:19867:0318/132307.476856:46918111666:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [19867:19867:0318/132307.477067:46918111877: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-03-18 19:10:08,364 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpDleA85/43ac81b2d0319910'] 2019-03-18 19:10:08,365 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpDleA85/43ac81b2d0319910/output.json'] 2019-03-18 19:10:08,365 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/6e0330/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552960825360393, "id": "8918596265545281392", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58476", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69593", "scheduler_invocation_id:9084026327520800160", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58476, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "parent_got_revision_cp": "refs/heads/master@{#641797}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "parent_got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "parent_got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27160}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "swarm_hashes": {"accessibility_unittests": "b7663b306729f0d246cc2c45453df701552cab98", "angle_unittests": "d0c24c1b00429d44b0e66f66362f295e70d8bd25", "app_shell_unittests": "3c8f9270f4554c031bd2f76627b30b90a00c3067", "aura_unittests": "e18df401d2e6e3ddf700ec92b824813e2926f83d", "base_unittests": "597993844ba3a0085baccb17549706b975b6fc42", "blink_common_unittests": "a2feddb9a4c7b14d96419aa33805aa3f9e1f38cd", "blink_fuzzer_unittests": "74ff3a19cbdf8588e1c7c3cf7fea33eb885e0aff", "blink_heap_unittests": "22834f276ae091b2805c0fa737ca8a5637fa0685", "blink_platform_unittests": "f77dfe45b6ba90bc78eb8d4e86f702607ed71911", "blink_unittests": "32f93d2157808db2ce92b2bf22ec794a57e76b12", "boringssl_crypto_tests": "dd6245609029a5ce6b2fe7c4dd0a711d90738f98", "boringssl_ssl_tests": "d5a2741c6d44a1b8f5a25ef9f3abf60ba5380675", "browser_tests": "7d1d70e85f43a47603a93781e68336313bc5d9b7", "cacheinvalidation_unittests": "92bae042efa4e707f1e9080f514af067db1848b9", "capture_unittests": "269807155e2fc4a2f3d003147664b9d0f5403d7c", "cast_unittests": "3063d13cde43b794eec0efd3083f5c0f4f9fb1df", "cc_unittests": "0e3c76904405745ff00130b39196b3d6b5ba7d4b", "chrome_app_unittests": "3a255ed41175c4be9753d27a2ee35620bbebc413", "chromedriver_unittests": "a94b005fe859e7eb288538277ffb5e8a0083fd5b", "components_browsertests": "255f881d47a90022eb5364dbc2732d16ac5a44e7", "components_unittests": "f3e25ebdfe7ab42b7f1e28c127a26096fd7f1c85", "compositor_unittests": "0df61d29ce76ad140d5b22892e32b49e0c237043", "content_browsertests": "4d724190be7e840b2708e7df42f7d730fc63218e", "content_unittests": "9669c1ab83fffdcbfee04de4ec10acf7694df2d5", "cronet_tests": "c72cec42aaeacd3b2f04b9408f8de15b9de83a62", "cronet_unittests": "07e1bfd03fa0e6314b053f0599309a7fad4c3711", "crypto_unittests": "dbf146e11fb53acf911e0fd24865f82020f83008", "dbus_unittests": "7eebafc657e9cd5b41553dba19019df1359daee3", "device_unittests": "92824c5d8114d7f2b4c18cd4e82b2d58bbdb7b49", "display_unittests": "d1b318b84834c6e483957bc076daad3105fd60ae", "events_unittests": "ef593b0e29860a54995e059afa7f2268e4260090", "extensions_browsertests": "3db65320bc0339db90be848ec7ada733cd85da66", "extensions_unittests": "22c39bac942226f71793dcb3f28887da9f1f3b93", "filesystem_service_unittests": "60b505b2a81b7a20b65d19d7de31b87f32609cf4", "gcm_unit_tests": "0feeb268aaef56dfd6119990fd577fcfdc22130e", "gfx_unittests": "b2b4ddda33c5a555e54114bea0df079f99a9aa55", "gl_tests": "f9df7365644ad807f7b11987c8e2bf8398723895", "gl_unittests": "be5ffe60c3c7960ca82ed9aaada0508b979d6337", "google_apis_unittests": "02da817d0ce539957f4f5b456c0a6d7901987b29", "gpu_unittests": "a06b163e6742d2f3814cbe3d9f059dd81b086083", "headless_browsertests": "6427d781d3497e40ea2158a0dfb71d262a44f36f", "headless_unittests": "624a81f0e0bee31ed0a1c588d710d99c280c2d29", "interactive_ui_tests": "9fd9ccf764a5cf0e52afd0d2e3c34cebbba49e66", "ipc_tests": "4d6f197a67d46c269f591818dda9333018ee5d3d", "jingle_unittests": "8e6a58c1c0d9630b5a63bf88a10da5bb0981396d", "latency_unittests": "cf14589a7b00fb7dc5d7143162e6b73fdc784b71", "leveldb_service_unittests": "338899d5219a7c53d1b8dcdb7429d548d489be84", "libjingle_xmpp_unittests": "4455d00bdbedec5d03a5ca0fb81c567e010bb872", "media_blink_unittests": "9a20bb67709f3412f02212ee992f6f66ce4c8f04", "media_service_unittests": "ebce42ae160b6cec86c60519fcf1814c99488833", "media_unittests": "adb88c06a25d33370ae48bf2a1c2a94ac7d6b9f3", "message_center_unittests": "4f36ae5487f032a6292a945fbf4883990e7bb23f", "midi_unittests": "6c28ae7045535f90ca3324a1e0b337e1cfdde15c", "mojo_core_unittests": "48f7d21a95ba17b282f4352bd3cf34fd24ae11ab", "mojo_unittests": "5db893a930262a987a3b7894d82299dd636508fb", "nacl_helper_nonsfi_unittests": "a078405317aeb2ff69aec85b8b0d41fff06731bd", "nacl_loader_unittests": "0469df00bb5798170016c5b3bc27634772a53ca5", "native_theme_unittests": "cabafa88273d5e18ce378225af94513be2926abc", "net_unittests": "b9341d304f40e5c42639eb59861d83c59a4e42c0", "pdf_unittests": "1e5701e94137aa105eff982b012333b2d34ba81f", "ppapi_unittests": "c18b79d3e09623d09b6d9c204de9948281447fe3", "printing_unittests": "6980251bc93f5b0dd85e343103027f1a3acf7d61", "remoting_unittests": "662ff8918de5aeb600888e87dfff7301ac7c8a50", "sandbox_linux_unittests": "3f45f9b49d729c1b3ae12010986bd8077d715fc6", "service_manager_unittests": "03798e7f9c84617fc95614168694c7749217bc09", "services_unittests": "b9d4d3b06905e6accb5627ca2393377ee4f428df", "shell_dialogs_unittests": "2f3b31ca61a6d16ba9c39519d5caca422f800265", "skia_unittests": "1d7fa2a11562793afa137dfc2ebae2681b2d0125", "snapshot_unittests": "c95f671222732bc82fec044006cca99e6118b0d4", "sql_unittests": "04506b73bbf42af7bdf99c04d6e49a817949c17c", "storage_unittests": "05de694a988c78732b0a78ba096e3f53e0e7e9e4", "sync_integration_tests": "85ff1dba4186a6bc20531e5aca23d5498f54d1c1", "traffic_annotation_auditor_unittests": "f85042f2c936ecd2524b029c34fc7c7626bf7877", "ui_base_unittests": "9c1b59442e56f0307a1073e17ebb87f559738f33", "ui_touch_selection_unittests": "1632794e393670370734f9ed70013334bb8de216", "unit_tests": "2d24ec9b0b42510f238e93f9adbf063960f5655a", "url_unittests": "7f919f7244dd68dec3e89c2f36d05460dd03750f", "views_unittests": "acf8a57f4bbfb7f3be497466b7bb3a6ced05d271", "viz_unittests": "b1a6202c164718f57ed00b41fc430f95624096ec", "vr_common_unittests": "386ad284015eee3ec211a43440bd6881c838e821", "vr_pixeltests": "36412ecd23e0e494238ebfa71597e494f0915191", "wm_unittests": "c87fc0f4e229af3602bc069b65eba7832c862575", "wtf_unittests": "bbccd30469140fd2b878ba2ef0872737c7ed5afa"}} --summary-json /b/swarming/w/ir/tmp/t/tmpN59H6n.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpDleA85 -o /b/swarming/w/ir/tmp/t/tmpmhSP8m.json /b/swarming/w/ir/tmp/t/tmpDleA85/43ac81b2d0319910/output.json Running ['/b/swarming/w/ir/cache/vpython/6e0330/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552960825360393, "id": "8918596265545281392", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58476", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69593", "scheduler_invocation_id:9084026327520800160", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58476, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "parent_got_revision_cp": "refs/heads/master@{#641797}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "parent_got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "parent_got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27160}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "swarm_hashes": {"accessibility_unittests": "b7663b306729f0d246cc2c45453df701552cab98", "angle_unittests": "d0c24c1b00429d44b0e66f66362f295e70d8bd25", "app_shell_unittests": "3c8f9270f4554c031bd2f76627b30b90a00c3067", "aura_unittests": "e18df401d2e6e3ddf700ec92b824813e2926f83d", "base_unittests": "597993844ba3a0085baccb17549706b975b6fc42", "blink_common_unittests": "a2feddb9a4c7b14d96419aa33805aa3f9e1f38cd", "blink_fuzzer_unittests": "74ff3a19cbdf8588e1c7c3cf7fea33eb885e0aff", "blink_heap_unittests": "22834f276ae091b2805c0fa737ca8a5637fa0685", "blink_platform_unittests": "f77dfe45b6ba90bc78eb8d4e86f702607ed71911", "blink_unittests": "32f93d2157808db2ce92b2bf22ec794a57e76b12", "boringssl_crypto_tests": "dd6245609029a5ce6b2fe7c4dd0a711d90738f98", "boringssl_ssl_tests": "d5a2741c6d44a1b8f5a25ef9f3abf60ba5380675", "browser_tests": "7d1d70e85f43a47603a93781e68336313bc5d9b7", "cacheinvalidation_unittests": "92bae042efa4e707f1e9080f514af067db1848b9", "capture_unittests": "269807155e2fc4a2f3d003147664b9d0f5403d7c", "cast_unittests": "3063d13cde43b794eec0efd3083f5c0f4f9fb1df", "cc_unittests": "0e3c76904405745ff00130b39196b3d6b5ba7d4b", "chrome_app_unittests": "3a255ed41175c4be9753d27a2ee35620bbebc413", "chromedriver_unittests": "a94b005fe859e7eb288538277ffb5e8a0083fd5b", "components_browsertests": "255f881d47a90022eb5364dbc2732d16ac5a44e7", "components_unittests": "f3e25ebdfe7ab42b7f1e28c127a26096fd7f1c85", "compositor_unittests": "0df61d29ce76ad140d5b22892e32b49e0c237043", "content_browsertests": "4d724190be7e840b2708e7df42f7d730fc63218e", "content_unittests": "9669c1ab83fffdcbfee04de4ec10acf7694df2d5", "cronet_tests": "c72cec42aaeacd3b2f04b9408f8de15b9de83a62", "cronet_unittests": "07e1bfd03fa0e6314b053f0599309a7fad4c3711", "crypto_unittests": "dbf146e11fb53acf911e0fd24865f82020f83008", "dbus_unittests": "7eebafc657e9cd5b41553dba19019df1359daee3", "device_unittests": "92824c5d8114d7f2b4c18cd4e82b2d58bbdb7b49", "display_unittests": "d1b318b84834c6e483957bc076daad3105fd60ae", "events_unittests": "ef593b0e29860a54995e059afa7f2268e4260090", "extensions_browsertests": "3db65320bc0339db90be848ec7ada733cd85da66", "extensions_unittests": "22c39bac942226f71793dcb3f28887da9f1f3b93", "filesystem_service_unittests": "60b505b2a81b7a20b65d19d7de31b87f32609cf4", "gcm_unit_tests": "0feeb268aaef56dfd6119990fd577fcfdc22130e", "gfx_unittests": "b2b4ddda33c5a555e54114bea0df079f99a9aa55", "gl_tests": "f9df7365644ad807f7b11987c8e2bf8398723895", "gl_unittests": "be5ffe60c3c7960ca82ed9aaada0508b979d6337", "google_apis_unittests": "02da817d0ce539957f4f5b456c0a6d7901987b29", "gpu_unittests": "a06b163e6742d2f3814cbe3d9f059dd81b086083", "headless_browsertests": "6427d781d3497e40ea2158a0dfb71d262a44f36f", "headless_unittests": "624a81f0e0bee31ed0a1c588d710d99c280c2d29", "interactive_ui_tests": "9fd9ccf764a5cf0e52afd0d2e3c34cebbba49e66", "ipc_tests": "4d6f197a67d46c269f591818dda9333018ee5d3d", "jingle_unittests": "8e6a58c1c0d9630b5a63bf88a10da5bb0981396d", "latency_unittests": "cf14589a7b00fb7dc5d7143162e6b73fdc784b71", "leveldb_service_unittests": "338899d5219a7c53d1b8dcdb7429d548d489be84", "libjingle_xmpp_unittests": "4455d00bdbedec5d03a5ca0fb81c567e010bb872", "media_blink_unittests": "9a20bb67709f3412f02212ee992f6f66ce4c8f04", "media_service_unittests": "ebce42ae160b6cec86c60519fcf1814c99488833", "media_unittests": "adb88c06a25d33370ae48bf2a1c2a94ac7d6b9f3", "message_center_unittests": "4f36ae5487f032a6292a945fbf4883990e7bb23f", "midi_unittests": "6c28ae7045535f90ca3324a1e0b337e1cfdde15c", "mojo_core_unittests": "48f7d21a95ba17b282f4352bd3cf34fd24ae11ab", "mojo_unittests": "5db893a930262a987a3b7894d82299dd636508fb", "nacl_helper_nonsfi_unittests": "a078405317aeb2ff69aec85b8b0d41fff06731bd", "nacl_loader_unittests": "0469df00bb5798170016c5b3bc27634772a53ca5", "native_theme_unittests": "cabafa88273d5e18ce378225af94513be2926abc", "net_unittests": "b9341d304f40e5c42639eb59861d83c59a4e42c0", "pdf_unittests": "1e5701e94137aa105eff982b012333b2d34ba81f", "ppapi_unittests": "c18b79d3e09623d09b6d9c204de9948281447fe3", "printing_unittests": "6980251bc93f5b0dd85e343103027f1a3acf7d61", "remoting_unittests": "662ff8918de5aeb600888e87dfff7301ac7c8a50", "sandbox_linux_unittests": "3f45f9b49d729c1b3ae12010986bd8077d715fc6", "service_manager_unittests": "03798e7f9c84617fc95614168694c7749217bc09", "services_unittests": "b9d4d3b06905e6accb5627ca2393377ee4f428df", "shell_dialogs_unittests": "2f3b31ca61a6d16ba9c39519d5caca422f800265", "skia_unittests": "1d7fa2a11562793afa137dfc2ebae2681b2d0125", "snapshot_unittests": "c95f671222732bc82fec044006cca99e6118b0d4", "sql_unittests": "04506b73bbf42af7bdf99c04d6e49a817949c17c", "storage_unittests": "05de694a988c78732b0a78ba096e3f53e0e7e9e4", "sync_integration_tests": "85ff1dba4186a6bc20531e5aca23d5498f54d1c1", "traffic_annotation_auditor_unittests": "f85042f2c936ecd2524b029c34fc7c7626bf7877", "ui_base_unittests": "9c1b59442e56f0307a1073e17ebb87f559738f33", "ui_touch_selection_unittests": "1632794e393670370734f9ed70013334bb8de216", "unit_tests": "2d24ec9b0b42510f238e93f9adbf063960f5655a", "url_unittests": "7f919f7244dd68dec3e89c2f36d05460dd03750f", "views_unittests": "acf8a57f4bbfb7f3be497466b7bb3a6ced05d271", "viz_unittests": "b1a6202c164718f57ed00b41fc430f95624096ec", "vr_common_unittests": "386ad284015eee3ec211a43440bd6881c838e821", "vr_pixeltests": "36412ecd23e0e494238ebfa71597e494f0915191", "wm_unittests": "c87fc0f4e229af3602bc069b65eba7832c862575", "wtf_unittests": "bbccd30469140fd2b878ba2ef0872737c7ed5afa"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpN59H6n.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpDleA85', '-o', '/b/swarming/w/ir/tmp/t/tmpmhSP8m.json', '/b/swarming/w/ir/tmp/t/tmpDleA85/43ac81b2d0319910/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/6e0330/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552960825360393, "id": "8918596265545281392", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58476", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69593", "scheduler_invocation_id:9084026327520800160", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58476, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "parent_got_revision_cp": "refs/heads/master@{#641797}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "parent_got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "parent_got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27160}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "swarm_hashes": {"accessibility_unittests": "b7663b306729f0d246cc2c45453df701552cab98", "angle_unittests": "d0c24c1b00429d44b0e66f66362f295e70d8bd25", "app_shell_unittests": "3c8f9270f4554c031bd2f76627b30b90a00c3067", "aura_unittests": "e18df401d2e6e3ddf700ec92b824813e2926f83d", "base_unittests": "597993844ba3a0085baccb17549706b975b6fc42", "blink_common_unittests": "a2feddb9a4c7b14d96419aa33805aa3f9e1f38cd", "blink_fuzzer_unittests": "74ff3a19cbdf8588e1c7c3cf7fea33eb885e0aff", "blink_heap_unittests": "22834f276ae091b2805c0fa737ca8a5637fa0685", "blink_platform_unittests": "f77dfe45b6ba90bc78eb8d4e86f702607ed71911", "blink_unittests": "32f93d2157808db2ce92b2bf22ec794a57e76b12", "boringssl_crypto_tests": "dd6245609029a5ce6b2fe7c4dd0a711d90738f98", "boringssl_ssl_tests": "d5a2741c6d44a1b8f5a25ef9f3abf60ba5380675", "browser_tests": "7d1d70e85f43a47603a93781e68336313bc5d9b7", "cacheinvalidation_unittests": "92bae042efa4e707f1e9080f514af067db1848b9", "capture_unittests": "269807155e2fc4a2f3d003147664b9d0f5403d7c", "cast_unittests": "3063d13cde43b794eec0efd3083f5c0f4f9fb1df", "cc_unittests": "0e3c76904405745ff00130b39196b3d6b5ba7d4b", "chrome_app_unittests": "3a255ed41175c4be9753d27a2ee35620bbebc413", "chromedriver_unittests": "a94b005fe859e7eb288538277ffb5e8a0083fd5b", "components_browsertests": "255f881d47a90022eb5364dbc2732d16ac5a44e7", "components_unittests": "f3e25ebdfe7ab42b7f1e28c127a26096fd7f1c85", "compositor_unittests": "0df61d29ce76ad140d5b22892e32b49e0c237043", "content_browsertests": "4d724190be7e840b2708e7df42f7d730fc63218e", "content_unittests": "9669c1ab83fffdcbfee04de4ec10acf7694df2d5", "cronet_tests": "c72cec42aaeacd3b2f04b9408f8de15b9de83a62", "cronet_unittests": "07e1bfd03fa0e6314b053f0599309a7fad4c3711", "crypto_unittests": "dbf146e11fb53acf911e0fd24865f82020f83008", "dbus_unittests": "7eebafc657e9cd5b41553dba19019df1359daee3", "device_unittests": "92824c5d8114d7f2b4c18cd4e82b2d58bbdb7b49", "display_unittests": "d1b318b84834c6e483957bc076daad3105fd60ae", "events_unittests": "ef593b0e29860a54995e059afa7f2268e4260090", "extensions_browsertests": "3db65320bc0339db90be848ec7ada733cd85da66", "extensions_unittests": "22c39bac942226f71793dcb3f28887da9f1f3b93", "filesystem_service_unittests": "60b505b2a81b7a20b65d19d7de31b87f32609cf4", "gcm_unit_tests": "0feeb268aaef56dfd6119990fd577fcfdc22130e", "gfx_unittests": "b2b4ddda33c5a555e54114bea0df079f99a9aa55", "gl_tests": "f9df7365644ad807f7b11987c8e2bf8398723895", "gl_unittests": "be5ffe60c3c7960ca82ed9aaada0508b979d6337", "google_apis_unittests": "02da817d0ce539957f4f5b456c0a6d7901987b29", "gpu_unittests": "a06b163e6742d2f3814cbe3d9f059dd81b086083", "headless_browsertests": "6427d781d3497e40ea2158a0dfb71d262a44f36f", "headless_unittests": "624a81f0e0bee31ed0a1c588d710d99c280c2d29", "interactive_ui_tests": "9fd9ccf764a5cf0e52afd0d2e3c34cebbba49e66", "ipc_tests": "4d6f197a67d46c269f591818dda9333018ee5d3d", "jingle_unittests": "8e6a58c1c0d9630b5a63bf88a10da5bb0981396d", "latency_unittests": "cf14589a7b00fb7dc5d7143162e6b73fdc784b71", "leveldb_service_unittests": "338899d5219a7c53d1b8dcdb7429d548d489be84", "libjingle_xmpp_unittests": "4455d00bdbedec5d03a5ca0fb81c567e010bb872", "media_blink_unittests": "9a20bb67709f3412f02212ee992f6f66ce4c8f04", "media_service_unittests": "ebce42ae160b6cec86c60519fcf1814c99488833", "media_unittests": "adb88c06a25d33370ae48bf2a1c2a94ac7d6b9f3", "message_center_unittests": "4f36ae5487f032a6292a945fbf4883990e7bb23f", "midi_unittests": "6c28ae7045535f90ca3324a1e0b337e1cfdde15c", "mojo_core_unittests": "48f7d21a95ba17b282f4352bd3cf34fd24ae11ab", "mojo_unittests": "5db893a930262a987a3b7894d82299dd636508fb", "nacl_helper_nonsfi_unittests": "a078405317aeb2ff69aec85b8b0d41fff06731bd", "nacl_loader_unittests": "0469df00bb5798170016c5b3bc27634772a53ca5", "native_theme_unittests": "cabafa88273d5e18ce378225af94513be2926abc", "net_unittests": "b9341d304f40e5c42639eb59861d83c59a4e42c0", "pdf_unittests": "1e5701e94137aa105eff982b012333b2d34ba81f", "ppapi_unittests": "c18b79d3e09623d09b6d9c204de9948281447fe3", "printing_unittests": "6980251bc93f5b0dd85e343103027f1a3acf7d61", "remoting_unittests": "662ff8918de5aeb600888e87dfff7301ac7c8a50", "sandbox_linux_unittests": "3f45f9b49d729c1b3ae12010986bd8077d715fc6", "service_manager_unittests": "03798e7f9c84617fc95614168694c7749217bc09", "services_unittests": "b9d4d3b06905e6accb5627ca2393377ee4f428df", "shell_dialogs_unittests": "2f3b31ca61a6d16ba9c39519d5caca422f800265", "skia_unittests": "1d7fa2a11562793afa137dfc2ebae2681b2d0125", "snapshot_unittests": "c95f671222732bc82fec044006cca99e6118b0d4", "sql_unittests": "04506b73bbf42af7bdf99c04d6e49a817949c17c", "storage_unittests": "05de694a988c78732b0a78ba096e3f53e0e7e9e4", "sync_integration_tests": "85ff1dba4186a6bc20531e5aca23d5498f54d1c1", "traffic_annotation_auditor_unittests": "f85042f2c936ecd2524b029c34fc7c7626bf7877", "ui_base_unittests": "9c1b59442e56f0307a1073e17ebb87f559738f33", "ui_touch_selection_unittests": "1632794e393670370734f9ed70013334bb8de216", "unit_tests": "2d24ec9b0b42510f238e93f9adbf063960f5655a", "url_unittests": "7f919f7244dd68dec3e89c2f36d05460dd03750f", "views_unittests": "acf8a57f4bbfb7f3be497466b7bb3a6ced05d271", "viz_unittests": "b1a6202c164718f57ed00b41fc430f95624096ec", "vr_common_unittests": "386ad284015eee3ec211a43440bd6881c838e821", "vr_pixeltests": "36412ecd23e0e494238ebfa71597e494f0915191", "wm_unittests": "c87fc0f4e229af3602bc069b65eba7832c862575", "wtf_unittests": "bbccd30469140fd2b878ba2ef0872737c7ed5afa"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpN59H6n.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpDleA85', '-o', '/b/swarming/w/ir/tmp/t/tmpmhSP8m.json', '/b/swarming/w/ir/tmp/t/tmpDleA85/43ac81b2d0319910/output.json'] returned exit code 0