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/tmpjLnm_H.json --task-output-dir /b/swarming/w/ir/tmp/t/tmp0m9HoQ --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/tmpiNIpx9merge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553454418169658, "id": "8918078695972117904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32287", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/24025d13a3d457e28cdbe59dc91e73222da3af1f", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44245", "scheduler_invocation_id:9083508758827879456", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32287, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "got_revision_cp": "refs/heads/master@{#643731}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "parent_got_revision_cp": "refs/heads/master@{#643731}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "swarm_hashes": {"accessibility_unittests": "e64b88bcbe1179f6d81f7362bec9d96500d520be", "angle_unittests": "8fa699180f64cc4627ea447ae53881dfd5a034af", "app_list_unittests": "02dfd89c154f0ae7a82ea0b7b68c4b0be571ef73", "app_shell_unittests": "73777bed4cba13bb28f4a7d238edab673566b75d", "ash_unittests": "71c06c977f3ddecdb74fd12661d242474288a023", "aura_unittests": "1b9e5dc39de4c717df48498790cdf12b15fb781b", "base_unittests": "9ba9ecb6397bc5bed5b74500b6f24971bdcff0d5", "blink_common_unittests": "823cae7dfe14609028b63870c4b96b24a0fdde88", "blink_fuzzer_unittests": "712e5000a70c39da2e906e66c66b1167aa65e653", "blink_heap_unittests": "d10d2e28509448b149e46e26a0238d9b70dcc555", "blink_platform_unittests": "9ad52b8e8746b870817252b592d55b5d36438ce5", "blink_unittests": "d9c80f0734c0dfc55f5692d012432cd36a78a423", "boringssl_crypto_tests": "f6fdd625df20aec1de05caea9eaff99624324db7", "boringssl_ssl_tests": "812ad09c691f6e5e77f0c609a7fde5ab83766887", "browser_tests": "609023ce3961c8df58a7c4ef7acde88153923785", "cacheinvalidation_unittests": "f5b8c2a16c5703e95b45e1611e972a42e4745c49", "capture_unittests": "e9f97f6ca3f90e7bf7b4bd07341b09db08c92f7d", "cast_unittests": "30d02dc5332b66aee36944938c9d8051b3a67aea", "cc_unittests": "5fd296bf750f9477cfee6a2d2ede98f789b1d84e", "chrome_app_unittests": "dfd553a30ceb86cd08ac4d11fd022ce26307f01a", "chromedriver_unittests": "54e2974eaa37cd52a213cc87cac9cd540ed43302", "chromeos_components_unittests": "750480a2563dd293370eebefc400d06280c8daac", "chromeos_unittests": "446839e3944954709f088e0de729f5fd18432f57", "components_browsertests": "666ee63506e175358d3faa5dea6aabb4e0a5e43a", "components_unittests": "139ab46c3afd42cd3c2e4c1e82b587ae84142c2e", "compositor_unittests": "0817c123a43f8f1099aae83ef34d90f873a56325", "content_browsertests": "ee7334ebb986f5f0cd857916aab0e4f7de0ee729", "content_unittests": "6aafc4ea763dfb1381c02f12cddb600e0cde0643", "crypto_unittests": "bda07e809950bad650f7bb959fd6e32fd06837ea", "dbus_unittests": "e0e6adbf24f46347b2eea8daae7257f215d9f307", "device_unittests": "c4794958338778463ccc0f69d19031c1593f8b9f", "display_unittests": "707228d56b71f0d77c0cbf192a01fafd97cadc4c", "events_unittests": "253bdab2bde8e77e14a74094f9225ff71d10417f", "exo_unittests": "74c47884c09aca11a207d4e376178ded43ae820e", "extensions_browsertests": "63dcd7c85eee8b2dcbcbb8d8028ab41a68927000", "extensions_unittests": "c6306fab457ffb23d7293663911a66f7afed0d6a", "filesystem_service_unittests": "29b1744b158e73e980a83e61a0049fba28cdce4d", "gcm_unit_tests": "bc0ce5e5f1d992f7db7c820eedc3d00d915e0937", "gfx_unittests": "e094f212a05ad9cb7ac2dc23f09d1fdffd0e6092", "gl_unittests_ozone": "c49b99e7d6c70746d1e09024933e112eb32adb35", "google_apis_unittests": "76bbdbbe5e3fd4ef5b8be4d2548a53c3c4054c8f", "gpu_unittests": "1229541f3884f792fdb08d179da79ad491355111", "interactive_ui_tests": "5cee9610508ce8f7992acb9f95a8751825fb60f3", "ipc_tests": "6c2011b2aefd70eea3dc896b535b3783cc29645e", "jingle_unittests": "50068a1a2c508cbcb908d44fb3b67c0ea56c5c85", "keyboard_unittests": "b7ea2e90dd1d1a9b77d3264c6fbd5576e65a692f", "latency_unittests": "0748e6338a4de70a5fc1fdbf4c45945b1608b545", "leveldb_service_unittests": "97879d672b0babd91397319a70b94998d9c94c18", "libjingle_xmpp_unittests": "45db1df7828a48e33cc02882dca6525f59220997", "media_blink_unittests": "aec5bd53c36ef67ae7918abf9d566e9d0247d4e7", "media_service_unittests": "dd1e477f5d78f22e5797973893d05df67cebd27a", "media_unittests": "3bc32a8830e7cbf60dbbae637705a878b5e67469", "message_center_unittests": "35e6c4683f17977e9276d49d630e963ea23eb0c2", "midi_unittests": "6171f1bd07632ac259259dcd2eb7606f7036733a", "mojo_core_unittests": "e56c8c4a3154c072c5cc8b2985973b66450a9a75", "mojo_unittests": "1d5e40b04cffe375e15bf7c2dcd20d1ef9d759cc", "nacl_helper_nonsfi_unittests": "c84ff16e368053268ff6f5a34881019c9e45d02b", "nacl_loader_unittests": "c3243886c503904b3bacf60cf76f1bf60b7186d9", "native_theme_unittests": "86a7643e5ff1e180b8a34dab91c73d128237261f", "net_unittests": "82baf73a24b292aa1b0cce9c9307e9eabbba18f2", "ozone_gl_unittests": "94872d0292c59a8cee50b4fab5ba084964eba34c", "ozone_unittests": "cc2e56782215e8a62da2078d0fd6c4841224e531", "ozone_x11_unittests": "d3b60c43ddf4c3c396c64eef166fa2c2d22bf991", "pdf_unittests": "4fdb74d082859f50d720cf576182dc50c2f8195b", "perfetto_unittests": "5d8c491c19c3ad4b1daeccf129f71a2bd76296ee", "ppapi_unittests": "11a2e33db41121e102fe6ef1fa8bc3ed0ae1c062", "printing_unittests": "1fe4efcf41a9000303704a209d861e8d743e9b71", "remoting_unittests": "d665c9b8faced5300a7533cffaa6429d9d4d4123", "sandbox_linux_unittests": "e4d1ad8374c33b847b8b152c3dcc9ca6460b9258", "service_manager_unittests": "48a9529c8e12243154f1157cabcced59e245212d", "services_unittests": "a0bfb13fe742a512c91308b5fe5aca42693af384", "shell_dialogs_unittests": "eab64e7bacea6e74780ab6c02a29d0e8c395c603", "skia_unittests": "2c8b235d87bd7fdac84b5a08afc867685b6417ff", "snapshot_unittests": "44a4a0e75988af52a03f63bf09d67fd66f597bf7", "sql_unittests": "4229bc5954144b61acac98a41d4a68090715f108", "storage_unittests": "a75e190f5d9531963eac4603f9d548e9b62e8814", "sync_integration_tests": "82adff571f088b812b692726564d052c72780763", "traffic_annotation_auditor_unittests": "26e49645f979d46bffb1150017e0e0918d59ce49", "ui_base_unittests": "eedbaea22c4ced7255de07eb534378f13fd82169", "ui_chromeos_unittests": "db62467aa3a708637ad388f6d8bc2c4c7f579949", "ui_touch_selection_unittests": "1fa57521330981c93a8e50bf535e366c45a5f9c5", "unit_tests": "bc4483b81e5fe3cbe2bc3afcdbcbf3cc125c7fa4", "url_unittests": "63bf0ac3962e57d89e9ee9d002342e06ac55ba66", "usage_time_limit_unittests": "815ea1bd8d3d8bc0a0b09368c7a9a278f2014dce", "views_unittests": "a29ec6cd2a1af6b5ab4679e90c9cf4977d7bb80d", "viz_unittests": "3b1558a6e2ea9927303f270d53f20fdab15833f9", "wayland_client_perftests": "255db5d049e103f0474ea814131278a3aa30c8b6", "wm_unittests": "d0b438227fba5194322231fd77e153acad8bbfa4", "wtf_unittests": "ba23313940818e93b11b06fa2a3ab7624c6391cd"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmpcseQNW.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/tmpb384lI.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/tmpjLnm_H.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp0m9HoQ', '--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/tmpiNIpx9merge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553454418169658, "id": "8918078695972117904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32287", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/24025d13a3d457e28cdbe59dc91e73222da3af1f", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44245", "scheduler_invocation_id:9083508758827879456", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32287, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "got_revision_cp": "refs/heads/master@{#643731}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "parent_got_revision_cp": "refs/heads/master@{#643731}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "swarm_hashes": {"accessibility_unittests": "e64b88bcbe1179f6d81f7362bec9d96500d520be", "angle_unittests": "8fa699180f64cc4627ea447ae53881dfd5a034af", "app_list_unittests": "02dfd89c154f0ae7a82ea0b7b68c4b0be571ef73", "app_shell_unittests": "73777bed4cba13bb28f4a7d238edab673566b75d", "ash_unittests": "71c06c977f3ddecdb74fd12661d242474288a023", "aura_unittests": "1b9e5dc39de4c717df48498790cdf12b15fb781b", "base_unittests": "9ba9ecb6397bc5bed5b74500b6f24971bdcff0d5", "blink_common_unittests": "823cae7dfe14609028b63870c4b96b24a0fdde88", "blink_fuzzer_unittests": "712e5000a70c39da2e906e66c66b1167aa65e653", "blink_heap_unittests": "d10d2e28509448b149e46e26a0238d9b70dcc555", "blink_platform_unittests": "9ad52b8e8746b870817252b592d55b5d36438ce5", "blink_unittests": "d9c80f0734c0dfc55f5692d012432cd36a78a423", "boringssl_crypto_tests": "f6fdd625df20aec1de05caea9eaff99624324db7", "boringssl_ssl_tests": "812ad09c691f6e5e77f0c609a7fde5ab83766887", "browser_tests": "609023ce3961c8df58a7c4ef7acde88153923785", "cacheinvalidation_unittests": "f5b8c2a16c5703e95b45e1611e972a42e4745c49", "capture_unittests": "e9f97f6ca3f90e7bf7b4bd07341b09db08c92f7d", "cast_unittests": "30d02dc5332b66aee36944938c9d8051b3a67aea", "cc_unittests": "5fd296bf750f9477cfee6a2d2ede98f789b1d84e", "chrome_app_unittests": "dfd553a30ceb86cd08ac4d11fd022ce26307f01a", "chromedriver_unittests": "54e2974eaa37cd52a213cc87cac9cd540ed43302", "chromeos_components_unittests": "750480a2563dd293370eebefc400d06280c8daac", "chromeos_unittests": "446839e3944954709f088e0de729f5fd18432f57", "components_browsertests": "666ee63506e175358d3faa5dea6aabb4e0a5e43a", "components_unittests": "139ab46c3afd42cd3c2e4c1e82b587ae84142c2e", "compositor_unittests": "0817c123a43f8f1099aae83ef34d90f873a56325", "content_browsertests": "ee7334ebb986f5f0cd857916aab0e4f7de0ee729", "content_unittests": "6aafc4ea763dfb1381c02f12cddb600e0cde0643", "crypto_unittests": "bda07e809950bad650f7bb959fd6e32fd06837ea", "dbus_unittests": "e0e6adbf24f46347b2eea8daae7257f215d9f307", "device_unittests": "c4794958338778463ccc0f69d19031c1593f8b9f", "display_unittests": "707228d56b71f0d77c0cbf192a01fafd97cadc4c", "events_unittests": "253bdab2bde8e77e14a74094f9225ff71d10417f", "exo_unittests": "74c47884c09aca11a207d4e376178ded43ae820e", "extensions_browsertests": "63dcd7c85eee8b2dcbcbb8d8028ab41a68927000", "extensions_unittests": "c6306fab457ffb23d7293663911a66f7afed0d6a", "filesystem_service_unittests": "29b1744b158e73e980a83e61a0049fba28cdce4d", "gcm_unit_tests": "bc0ce5e5f1d992f7db7c820eedc3d00d915e0937", "gfx_unittests": "e094f212a05ad9cb7ac2dc23f09d1fdffd0e6092", "gl_unittests_ozone": "c49b99e7d6c70746d1e09024933e112eb32adb35", "google_apis_unittests": "76bbdbbe5e3fd4ef5b8be4d2548a53c3c4054c8f", "gpu_unittests": "1229541f3884f792fdb08d179da79ad491355111", "interactive_ui_tests": "5cee9610508ce8f7992acb9f95a8751825fb60f3", "ipc_tests": "6c2011b2aefd70eea3dc896b535b3783cc29645e", "jingle_unittests": "50068a1a2c508cbcb908d44fb3b67c0ea56c5c85", "keyboard_unittests": "b7ea2e90dd1d1a9b77d3264c6fbd5576e65a692f", "latency_unittests": "0748e6338a4de70a5fc1fdbf4c45945b1608b545", "leveldb_service_unittests": "97879d672b0babd91397319a70b94998d9c94c18", "libjingle_xmpp_unittests": "45db1df7828a48e33cc02882dca6525f59220997", "media_blink_unittests": "aec5bd53c36ef67ae7918abf9d566e9d0247d4e7", "media_service_unittests": "dd1e477f5d78f22e5797973893d05df67cebd27a", "media_unittests": "3bc32a8830e7cbf60dbbae637705a878b5e67469", "message_center_unittests": "35e6c4683f17977e9276d49d630e963ea23eb0c2", "midi_unittests": "6171f1bd07632ac259259dcd2eb7606f7036733a", "mojo_core_unittests": "e56c8c4a3154c072c5cc8b2985973b66450a9a75", "mojo_unittests": "1d5e40b04cffe375e15bf7c2dcd20d1ef9d759cc", "nacl_helper_nonsfi_unittests": "c84ff16e368053268ff6f5a34881019c9e45d02b", "nacl_loader_unittests": "c3243886c503904b3bacf60cf76f1bf60b7186d9", "native_theme_unittests": "86a7643e5ff1e180b8a34dab91c73d128237261f", "net_unittests": "82baf73a24b292aa1b0cce9c9307e9eabbba18f2", "ozone_gl_unittests": "94872d0292c59a8cee50b4fab5ba084964eba34c", "ozone_unittests": "cc2e56782215e8a62da2078d0fd6c4841224e531", "ozone_x11_unittests": "d3b60c43ddf4c3c396c64eef166fa2c2d22bf991", "pdf_unittests": "4fdb74d082859f50d720cf576182dc50c2f8195b", "perfetto_unittests": "5d8c491c19c3ad4b1daeccf129f71a2bd76296ee", "ppapi_unittests": "11a2e33db41121e102fe6ef1fa8bc3ed0ae1c062", "printing_unittests": "1fe4efcf41a9000303704a209d861e8d743e9b71", "remoting_unittests": "d665c9b8faced5300a7533cffaa6429d9d4d4123", "sandbox_linux_unittests": "e4d1ad8374c33b847b8b152c3dcc9ca6460b9258", "service_manager_unittests": "48a9529c8e12243154f1157cabcced59e245212d", "services_unittests": "a0bfb13fe742a512c91308b5fe5aca42693af384", "shell_dialogs_unittests": "eab64e7bacea6e74780ab6c02a29d0e8c395c603", "skia_unittests": "2c8b235d87bd7fdac84b5a08afc867685b6417ff", "snapshot_unittests": "44a4a0e75988af52a03f63bf09d67fd66f597bf7", "sql_unittests": "4229bc5954144b61acac98a41d4a68090715f108", "storage_unittests": "a75e190f5d9531963eac4603f9d548e9b62e8814", "sync_integration_tests": "82adff571f088b812b692726564d052c72780763", "traffic_annotation_auditor_unittests": "26e49645f979d46bffb1150017e0e0918d59ce49", "ui_base_unittests": "eedbaea22c4ced7255de07eb534378f13fd82169", "ui_chromeos_unittests": "db62467aa3a708637ad388f6d8bc2c4c7f579949", "ui_touch_selection_unittests": "1fa57521330981c93a8e50bf535e366c45a5f9c5", "unit_tests": "bc4483b81e5fe3cbe2bc3afcdbcbf3cc125c7fa4", "url_unittests": "63bf0ac3962e57d89e9ee9d002342e06ac55ba66", "usage_time_limit_unittests": "815ea1bd8d3d8bc0a0b09368c7a9a278f2014dce", "views_unittests": "a29ec6cd2a1af6b5ab4679e90c9cf4977d7bb80d", "viz_unittests": "3b1558a6e2ea9927303f270d53f20fdab15833f9", "wayland_client_perftests": "255db5d049e103f0474ea814131278a3aa30c8b6", "wm_unittests": "d0b438227fba5194322231fd77e153acad8bbfa4", "wtf_unittests": "ba23313940818e93b11b06fa2a3ab7624c6391cd"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmpcseQNW.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/tmpb384lI.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests',) ok_ret: ALL_OK step_test_data: <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: 45582 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/8918078695972117904 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/iteI8iSk/luci_context.862925605 MAC_CHROMIUM_TMPDIR: /b/swarming/w/ir/tmp/t METHOD: dhcp NO_GCE_CHECK: False PATH: /b/swarming/w/ir/cache/swarming_client:/b/swarming/w/ir/cipd_bin_packages:/b/swarming/w/ir/cipd_bin_packages/bin:/b/swarming/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin PWD: /b/swarming/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 ROOT_SETUP_LOG: /var/log/messages/chromebuild/root-setup.log SHLVL: 1 STARTUP_LOG: /var/log/messages/chromebuild/startup.log SWARMING_BOT_ID: swarm2376-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43c9ead2d9431d11 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-24 12:15:37,373 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmp0m9HoQ' 2019-03-24 12:15:37,373 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmp0m9HoQ' already exists! 2019-03-24 12:15:37,373 - root: [WARNING] task_output_dir existing content: [] 2019-03-24 12:15:37,374 - 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/tmpb384lI.json -output-dir /b/swarming/w/ir/tmp/t/tmp0m9HoQ -task-summary-json /b/swarming/w/ir/tmp/t/tmpcseQNW.json [D2019-03-24T12:15:37.381613-07:00 14940 0 auth.go:1265] Minting a new token {"key":"luci_ctx/5aabde927319056f57ecdb77e002107bb74b87a03e85f1978aa60127697c52bd", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-24T12:15:37.381688-07:00 14940 0 luci_ctx.go:138] POST http://127.0.0.1:46402/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/5aabde927319056f57ecdb77e002107bb74b87a03e85f1978aa60127697c52bd", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-24T12:15:37.384167-07:00 14940 0 auth.go:1222] Token expires in 26m46.615875958s {"key":"luci_ctx/5aabde927319056f57ecdb77e002107bb74b87a03e85f1978aa60127697c52bd", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43c9ee43dc0b8a10: 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/ioebdMPo/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 [26391:26391:0324/002439.233731:11875875256:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000ff0 with delay 0 [26391:26391:0324/002439.233990:11875875388:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000ff0 [26391:26391:0324/002439.234450:11875875843: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 } [26391:26391:0324/002439.234554:11875875945:INFO:recurring-task.cc(55)] [Send-info] Scheduling 17192 with a delay 500000, Now = 210919424 [26391:26391:0324/002439.234598:11875875988:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001030 with delay 500 [26391:26391:0324/002439.234802:11875876193:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001030 [26391:26391:0324/002439.234904:11875876401:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [26391:26391:0324/002439.235088:11875876478:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) [1/28] ProtocolHandlerTest.TokenMissing (2 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [26391:26391:0324/002439.235774:11875877170:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000015b0 with delay 0 [26391:26391:0324/002439.235837:11875877228:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000015b0 [26391:26391:0324/002439.235900:11875877290:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 22184 with a delay 500000, Now = 210919424 [26391:26391:0324/002439.235946:11875877337:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000015d0 with delay 500 [26391:26391:0324/002439.236100:11875877491:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000015d0 [26391:26391:0324/002439.236252:11875877643:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [26391:26391:0324/002439.236349:11875877740: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 } [26391:26391:0324/002439.236452:11875877846: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 } } [26391:26391:0324/002439.236702:11875878092: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 } } } [26391:26391:0324/002439.236882:11875878276: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 [26391:26391:0324/002439.237722:11875879115:INFO:protocol-handler.cc(139)] Incoming message: { } [26391:26391:0324/002439.237781:11875879171:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [26391:26391:0324/002439.237824:11875879215:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [ RUN ] RecurringTaskTest.PeriodicTask [26391:26391:0324/002439.238209:11875879609:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -1973472152 with a delay 10000, Now = 0 [26391:26391:0324/002439.238281:11875879673:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000001c90 with delay 10 [26391:26391:0324/002439.238346:11875879740:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000001c90 [26391:26391:0324/002439.238391:11875879781:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [26391:26391:0324/002439.238444:11875879836:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973472152 with a delay 60000, Now = 10000 [26391:26391:0324/002439.238485:11875879878:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000001cb0 with delay 60 [26391:26391:0324/002439.238723:11875880112:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000001cb0 [26391:26391:0324/002439.238770:11875880159:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [26391:26391:0324/002439.238800:11875880186:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973472152 with a delay 60000, Now = 70000 [26391:26391:0324/002439.238825:11875880214:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x602000001cd0 with delay 60 [26391:26391:0324/002439.238879:11875880265:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x602000001cd0 [26391:26391:0324/002439.238902:11875880287:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [26391:26391:0324/002439.238928:11875880313:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973472152 with a delay 60000, Now = 130000 [26391:26391:0324/002439.238947:11875880337:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x602000001cf0 with delay 60 [26391:26391:0324/002439.238976:11875880361:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x602000001cf0 [26391:26391:0324/002439.239002:11875880390:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [26391:26391:0324/002439.239030:11875880418:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973472152 with a delay 60000, Now = 190000 [26391:26391:0324/002439.239052:11875880439:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x602000001d10 with delay 60 [26391:26391:0324/002439.239084:11875880470:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x602000001d10 [26391:26391:0324/002439.239103:11875880491:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [26391:26391:0324/002439.239125:11875880511:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973472152 with a delay 60000, Now = 250000 [26391:26391:0324/002439.239146:11875880530:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000001d30 with delay 60 [26391:26391:0324/002439.239167:11875880552:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000001d30 [26391:26391:0324/002439.239253:11875880638:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [26391:26391:0324/002439.239284:11875880670:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973472152 with a delay 60000, Now = 310000 [26391:26391:0324/002439.239323:11875880709:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000001d50 with delay 60 [26391:26391:0324/002439.239352:11875880739:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000001d50 [26391:26391:0324/002439.239377:11875880763:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [26391:26391:0324/002439.239400:11875880785:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973472152 with a delay 60000, Now = 370000 [26391:26391:0324/002439.239424:11875880810:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000001d70 with delay 60 [26391:26391:0324/002439.239452:11875880840:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000001d70 [26391:26391:0324/002439.239487:11875880873:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (2 ms) [4/28] RecurringTaskTest.PeriodicTask (2 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [26391:26391:0324/002439.240808:11875882196:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -1973616536 with a delay 10000, Now = 0 [26391:26391:0324/002439.240855:11875882242:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000001df0 with delay 10 [26391:26391:0324/002439.240916:11875882302:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000001df0 [26391:26391:0324/002439.240949:11875882335:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [26391:26391:0324/002439.240998:11875882387:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973616536 with a delay 50000, Now = 10000 [26391:26391:0324/002439.241029:11875882414:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000001e10 with delay 50 [26391:26391:0324/002439.241058:11875882444:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000001e10 [26391:26391:0324/002439.241088:11875882474:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [26391:26391:0324/002439.241118:11875882503:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973616536 with a delay 149000, Now = 60000 [26391:26391:0324/002439.241139:11875882525:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000001e30 with delay 149 [26391:26391:0324/002439.241171:11875882557:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000001e30 [26391:26391:0324/002439.241192:11875882580:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [26391:26391:0324/002439.241225:11875882633:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973616536 with a delay 248000, Now = 210000 [26391:26391:0324/002439.241275:11875882661:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000001e50 with delay 248 [26391:26391:0324/002439.241312:11875882698:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000001e50 [26391:26391:0324/002439.241338:11875882724:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [26391:26391:0324/002439.241505:11875882890:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973616536 with a delay 446000, Now = 460000 [26391:26391:0324/002439.241530:11875882919:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000001e70 with delay 446 [26391:26391:0324/002439.241575:11875882961:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000001e70 [26391:26391:0324/002439.241603:11875882988:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [26391:26391:0324/002439.241638:11875883024:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973616536 with a delay 842000, Now = 910000 [26391:26391:0324/002439.241662:11875883049:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000001e90 with delay 842 [26391:26391:0324/002439.241707:11875883092:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000001e90 [26391:26391:0324/002439.241734:11875883125:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [26391:26391:0324/002439.241765:11875883150:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973616536 with a delay 1040000, Now = 1760000 [26391:26391:0324/002439.241785:11875883171:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000001eb0 with delay 1040 [26391:26391:0324/002439.241826:11875883211:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000001eb0 [26391:26391:0324/002439.241852:11875883242:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [26391:26391:0324/002439.241883:11875883269:INFO:recurring-task.cc(55)] [Retry] Scheduling -1973616536 with a delay 1040000, Now = 2800000 [26391:26391:0324/002439.241917:11875883303:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000001ed0 with delay 1040 [26391:26391:0324/002439.241958:11875883344:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000001ed0 [26391:26391:0324/002439.241976:11875883364:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms) [ RUN ] RecurringTaskTest.OneShotTask [26391:26391:0324/002439.242947:11875884335:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -1973627800 with a delay 10000, Now = 0 [26391:26391:0324/002439.242986:11875884371:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000001f50 with delay 10 [26391:26391:0324/002439.243025:11875884411:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000001f50 [26391:26391:0324/002439.243050:11875884436:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [26391:26391:0324/002439.243134:11875884520:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -1973627800 with a delay 10000, Now = 10000 [26391:26391:0324/002439.243160:11875884545:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000001f70 with delay 10 [26391:26391:0324/002439.243185:11875884572:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000001f70 [26391:26391:0324/002439.243222:11875884609:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [6/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [26391:26391:0324/002439.244289:11875885688:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000001ff0 with delay 920 [26391:26391:0324/002439.244367:11875885754:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000001ff0 [26391:26391:0324/002439.244656:11875886045:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002010 with delay 45000 [26391:26391:0324/002439.245475:11875886862:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002010 [ OK ] ThrottleTest.ThrottlingScripted (1 ms) [7/28] ThrottleTest.ThrottlingScripted (1 ms) [ RUN ] ThrottleTest.ThrottlingStorm [26391:26391:0324/002439.245619:11875887006:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002090 with delay 990 [26391:26391:0324/002439.245686:11875887071:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002090 [26391:26391:0324/002439.245726:11875887111:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x6020000020b0 with delay 1000 [26391:26391:0324/002439.245776:11875887165:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x6020000020b0 [26391:26391:0324/002439.245801:11875887187:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x6020000020d0 with delay 1000 [26391:26391:0324/002439.245851:11875887236:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x6020000020d0 [26391:26391:0324/002439.245870:11875887255:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x6020000020f0 with delay 1000 [26391:26391:0324/002439.245921:11875887307:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x6020000020f0 [26391:26391:0324/002439.245949:11875887335:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002110 with delay 1000 [26391:26391:0324/002439.245998:11875887385:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002110 [26391:26391:0324/002439.246020:11875887404:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002130 with delay 1000 [26391:26391:0324/002439.246089:11875887476:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002130 [26391:26391:0324/002439.246119:11875887504:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002150 with delay 54000 [26391:26391:0324/002439.247856:11875889245:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002150 [26391:26391:0324/002439.247893:11875889280:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002170 with delay 1000 [26391:26391:0324/002439.247951:11875889337:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002170 [26391:26391:0324/002439.247987:11875889386:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002190 with delay 1000 [26391:26391:0324/002439.248075:11875889462:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002190 [26391:26391:0324/002439.248100:11875889486:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x6020000021b0 with delay 1000 [26391:26391:0324/002439.248149:11875889534:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x6020000021b0 [26391:26391:0324/002439.248172:11875889557:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x6020000021d0 with delay 1000 [26391:26391:0324/002439.248223:11875889608:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x6020000021d0 [26391:26391:0324/002439.248242:11875889626:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x6020000021f0 with delay 1000 [26391:26391:0324/002439.248306:11875889692:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x6020000021f0 [26391:26391:0324/002439.248334:11875889720:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002210 with delay 1000 [26391:26391:0324/002439.248389:11875889773:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002210 [26391:26391:0324/002439.248407:11875889799:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002230 with delay 54000 [26391:26391:0324/002439.250095:11875891483:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002230 [26391:26391:0324/002439.250130:11875891516:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002250 with delay 1000 [26391:26391:0324/002439.250198:11875891583:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002250 [26391:26391:0324/002439.250218:11875891603:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002270 with delay 1000 [26391:26391:0324/002439.250266:11875891650:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002270 [26391:26391:0324/002439.250284:11875891714:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002290 with delay 1000 [26391:26391:0324/002439.250382:11875891767:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002290 [26391:26391:0324/002439.250402:11875891787:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x6020000022b0 with delay 1000 [26391:26391:0324/002439.250455:11875891841:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x6020000022b0 [26391:26391:0324/002439.250474:11875891859:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x6020000022d0 with delay 1000 [26391:26391:0324/002439.250521:11875891906:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x6020000022d0 [26391:26391:0324/002439.250540:11875891929:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x6020000022f0 with delay 1000 [26391:26391:0324/002439.250592:11875891976:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x6020000022f0 [26391:26391:0324/002439.250611:11875891997:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002310 with delay 54000 [26391:26391:0324/002439.252286:11875893682:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002310 [26391:26391:0324/002439.252332:11875893718:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000002330 with delay 1000 [26391:26391:0324/002439.252402:11875893789:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000002330 [26391:26391:0324/002439.252444:11875893833:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000002350 with delay 1000 [26391:26391:0324/002439.252509:11875893894:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000002350 [26391:26391:0324/002439.252531:11875893917:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000002370 with delay 1000 [26391:26391:0324/002439.252579:11875893964:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000002370 [26391:26391:0324/002439.252598:11875893982:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000002390 with delay 1000 [26391:26391:0324/002439.252645:11875894030:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000002390 [26391:26391:0324/002439.252672:11875894057:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x6020000023b0 with delay 1000 [26391:26391:0324/002439.252720:11875894105:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x6020000023b0 [26391:26391:0324/002439.252739:11875894123:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000023d0 with delay 1000 [26391:26391:0324/002439.252786:11875894170:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000023d0 [26391:26391:0324/002439.252865:11875894251:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000023f0 with delay 54000 [26391:26391:0324/002439.254525:11875895911:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000023f0 [26391:26391:0324/002439.254560:11875895946:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x602000002410 with delay 1000 [26391:26391:0324/002439.254610:11875895995:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x602000002410 [26391:26391:0324/002439.254648:11875896033:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000002430 with delay 1000 [26391:26391:0324/002439.254728:11875896115:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000002430 [26391:26391:0324/002439.254755:11875896140:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000002450 with delay 1000 [26391:26391:0324/002439.254814:11875896199:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000002450 [26391:26391:0324/002439.254838:11875896225:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000002470 with delay 1000 [26391:26391:0324/002439.254888:11875896272:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000002470 [26391:26391:0324/002439.254906:11875896292:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000002490 with delay 1000 [26391:26391:0324/002439.254959:11875896344:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000002490 [26391:26391:0324/002439.254978:11875896363:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x6020000024b0 with delay 1000 [26391:26391:0324/002439.255029:11875896416:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x6020000024b0 [26391:26391:0324/002439.255062:11875896449:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000024d0 with delay 54000 [26391:26391:0324/002439.256820:11875898208:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000024d0 [ OK ] ThrottleTest.ThrottlingStorm (11 ms) [8/28] ThrottleTest.ThrottlingStorm (11 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [26390:26390:0324/002439.228252:11875869758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000ff0 with delay 0 [26390:26390:0324/002439.228909:11875870308:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000ff0 [26390:26390:0324/002439.229310:11875870706: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 } [26390:26390:0324/002439.229392:11875870783:INFO:recurring-task.cc(55)] [Startup] Scheduling 17192 with a delay 500000, Now = 210919424 [26390:26390:0324/002439.229459:11875870851:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000011b0 with delay 500 [26390:26390:0324/002439.229571:11875870963:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000011b0 [26390:26390:0324/002439.230055:11875871447: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 (4 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (4 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [26390:26390:0324/002439.232420:11875873813: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 [26390:26390:0324/002439.233378:11875874769:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001df0 with delay 0 [26390:26390:0324/002439.233588:11875874980:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e10 with delay 0 [26390:26390:0324/002439.233648:11875875040:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e30 with delay 0 [26390:26390:0324/002439.233744:11875875140:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e50 with delay 0 [26390:26390:0324/002439.233810:11875875207:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e70 with delay 0 [26390:26390:0324/002439.233932:11875875322:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 0 [26390:26390:0324/002439.234676:11875876068:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001df0 [26390:26390:0324/002439.234822:11875876214: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 } [26390:26390:0324/002439.234966:11875876360:INFO:recurring-task.cc(55)] [Send-info] Scheduling 28712 with a delay 500000, Now = 210919424 [26390:26390:0324/002439.235031:11875876423:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 500 [26390:26390:0324/002439.235088:11875876477:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e10 [26390:26390:0324/002439.235149:11875876538:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e30 [26390:26390:0324/002439.235190:11875876581:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e50 [26390:26390:0324/002439.235231:11875876625:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e70 [26390:26390:0324/002439.235276:11875876670:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e90 [26390:26390:0324/002439.235366:11875876765:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [26390:26390:0324/002439.235483:11875876874:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002030 [26390:26390:0324/002439.235838:11875877230:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [26390:26390:0324/002439.236606:11875878000:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } registration_message: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } registration: { object_id: { source: 2 name: "oid1" } op_type: UNREGISTER } registration: { object_id: { source: 2 name: "oid2" } op_type: UNREGISTER } } registration_sync_message: { subtree: { registered_object: { source: 2 name: "oid0" } } } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "unit-test" } performance_counter: { name: "x" value: 3 } performance_counter: { name: "y" value: 81 } server_registration_summary_requested: true } } [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (6 ms) [11/28] ProtocolHandlerTest.SendMultipleMessageTypes (6 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [26390:26390:0324/002439.239469:11875880860: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 [26390:26390:0324/002439.240184:11875881573: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 } } [26390:26390:0324/002439.240276:11875881668: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" } [26390:26390:0324/002439.240416:11875881803: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 } } [26390:26390:0324/002439.240582:11875881971: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 [26390:26390:0324/002439.241171:11875882560: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 } } [26390:26390:0324/002439.241313:11875882700:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [14/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [26390:26390:0324/002439.241884:11875883273: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 [26390:26390:0324/002439.242542:11875883931: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" } } [26390:26390:0324/002439.242620:11875884030:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b70 with delay 0 [26390:26390:0324/002439.242673:11875884061:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b70 [26390:26390:0324/002439.242748:11875884135: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 } [26390:26390:0324/002439.242799:11875884185:INFO:recurring-task.cc(55)] [Send-info] Scheduling 59816 with a delay 500000, Now = 210919424 [26390:26390:0324/002439.242835:11875884224:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 500 [26390:26390:0324/002439.242974:11875884360:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003b90 [26390:26390:0324/002439.243002:11875884395:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (36 ms) [16/28] ProtocolHandlerTest.ConfigMessage (36 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [26390:26390:0324/002439.278780:11875920171: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 [26390:26390:0324/002439.279234:11875920622: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 [26387:26387:0324/002439.209984:11875851521:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001330 with delay 0 [26387:26387:0324/002439.210515:11875851903:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.210997:11875852393:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001870 with delay 0 [26387:26387:0324/002439.211062:11875852451:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001330 [26387:26387:0324/002439.211982:11875853369:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001870 [26387:26387:0324/002439.212062:11875853450:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.212267:11875853658:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001930 with delay 0 [26387:26387:0324/002439.212364:11875853751:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001930 [26387:26387:0324/002439.212392:11875853778:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.212446:11875853833:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001970 with delay 0 [26387:26387:0324/002439.212506:11875853893:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001970 [26387:26387:0324/002439.212542:11875853928:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.212620:11875854007:INFO:recurring-task.cc(55)] [Startup] Scheduling 17448 with a delay 0, Now = 210919424 [26387:26387:0324/002439.212664:11875854054:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001990 with delay 0 [26387:26387:0324/002439.212702:11875854092:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001990 [26387:26387:0324/002439.212812:11875854201:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2786032505381669965" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.212853:11875854239:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 17704 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.212890:11875854276:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000019b0 with delay 500 [26387:26387:0324/002439.212914:11875854299:INFO:recurring-task.cc(55)] [Retry] Scheduling 17448 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.212962:11875854348:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000019d0 with delay 60000 [26387:26387:0324/002439.213058:11875854444:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000019b0 [26387:26387:0324/002439.213116:11875854508:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.213209:11875854594:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.213469:11875854856: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: "2786032505381669965" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.213804:11875855191:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001a70 with delay 0 [26387:26387:0324/002439.213841:11875855230:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001a70 [26387:26387:0324/002439.214077:11875855476:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2786032505381669965" 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" } } [26387:26387:0324/002439.214190:11875855576:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2786032505381669965" [26387:26387:0324/002439.214224:11875855618:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.214278:11875855665:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13096 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.214325:11875855716:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001a90 with delay 1200000 [26387:26387:0324/002439.214364:11875855758:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.214713:11875856101:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.214764:11875856150:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 3528 with a delay 0, Now = 211419424 [26387:26387:0324/002439.214797:11875856184:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001cb0 with delay 0 [26387:26387:0324/002439.214853:11875856276: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 [26387:26387:0324/002439.214946:11875856333:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001cb0 [26387:26387:0324/002439.215067:11875856454:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001d70 with delay 0 [26387:26387:0324/002439.215124:11875856510:INFO:recurring-task.cc(55)] [Retry] Scheduling 3528 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.215161:11875856548:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001db0 with delay 10000 [26387:26387:0324/002439.215202:11875856592:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d70 [26387:26387:0324/002439.215231:11875856620:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (7 ms) [19/28] InvalidationClientImplTest.Start (7 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [26387:26387:0324/002439.216275:11875857664:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0 [26387:26387:0324/002439.216341:11875857728: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 [26387:26387:0324/002439.216897:11875858285:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002eb0 with delay 0 [26387:26387:0324/002439.216949:11875858336:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.217359:11875858748:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003510 with delay 0 [26387:26387:0324/002439.217403:11875858794:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002eb0 [26387:26387:0324/002439.217445:11875858831:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003510 [26387:26387:0324/002439.217517:11875858904:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.217577:11875858974:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000035d0 with delay 0 [26387:26387:0324/002439.217618:11875859004:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000035d0 [26387:26387:0324/002439.217645:11875859100:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.217750:11875859141:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003610 with delay 0 [26387:26387:0324/002439.217785:11875859171:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003610 [26387:26387:0324/002439.217835:11875859222:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.217869:11875859256:INFO:recurring-task.cc(55)] [Startup] Scheduling 41384 with a delay 0, Now = 210919424 [26387:26387:0324/002439.217904:11875859294:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003630 with delay 0 [26387:26387:0324/002439.217949:11875859344:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003630 [26387:26387:0324/002439.218043:11875859429:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6604797551953645048" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.218076:11875859463:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 41640 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.218108:11875859500:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003650 with delay 500 [26387:26387:0324/002439.218178:11875859573:INFO:recurring-task.cc(55)] [Retry] Scheduling 41384 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.218217:11875859609:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003670 with delay 60000 [26387:26387:0324/002439.218354:11875859741:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003650 [26387:26387:0324/002439.218393:11875859780:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.218440:11875859832:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.218568:11875859958: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: "-6604797551953645048" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.218724:11875860111:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003710 with delay 0 [26387:26387:0324/002439.218765:11875860152:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003710 [26387:26387:0324/002439.218869:11875860256:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6604797551953645048" 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" } } [26387:26387:0324/002439.219001:11875860389:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6604797551953645048" [26387:26387:0324/002439.219037:11875860427:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.219073:11875860462:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15384 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.219112:11875860498:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003730 with delay 1200000 [26387:26387:0324/002439.219156:11875860542:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.219287:11875860672:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.219339:11875860752:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 7944 with a delay 0, Now = 211419424 [26387:26387:0324/002439.219399:11875860790:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003950 with delay 0 [26387:26387:0324/002439.219457:11875860844: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 [26387:26387:0324/002439.219502:11875860888:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003950 [26387:26387:0324/002439.219667:11875861053:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003a10 with delay 0 [26387:26387:0324/002439.219716:11875861110:INFO:recurring-task.cc(55)] [Retry] Scheduling 7944 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.219758:11875861149:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003a50 with delay 10000 [26387:26387:0324/002439.219802:11875861189:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003a10 [26387:26387:0324/002439.219827:11875861220:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.219912:11875861300:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003a70 with delay 0 [26387:26387:0324/002439.219944:11875861334:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000003a70 [26387:26387:0324/002439.219996:11875861383:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [26387:26387:0324/002439.220034:11875861420:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [26387:26387:0324/002439.220064:11875861449:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [26387:26387:0324/002439.220194:11875861581:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 41640 with a delay 500000, Now = 211469424 [26387:26387:0324/002439.220236:11875861622:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003a90 with delay 500 [26387:26387:0324/002439.220267:11875861654:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 41512 with a delay 60000000, Now = 211469424 [26387:26387:0324/002439.220312:11875861703:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003ab0 with delay 60000 [26387:26387:0324/002439.220544:11875861934:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000003a90 [26387:26387:0324/002439.220592:11875861979:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.220657:11875862045:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.220686:11875862074:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [26387:26387:0324/002439.220874:11875862262: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 } } } [26387:26387:0324/002439.220976:11875862363:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.221091:11875862479:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000003b50 with delay 0 [26387:26387:0324/002439.221136:11875862522:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000003b50 [26387:26387:0324/002439.221373:11875862767: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 } } } } [26387:26387:0324/002439.221467:11875862854: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 [26387:26387:0324/002439.221535:11875862922:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [26387:26387:0324/002439.221695:11875863081:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [26387:26387:0324/002439.221764:11875863150:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [26387:26387:0324/002439.222316:11875863705:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000003a50 [ OK ] InvalidationClientImplTest.Register (7 ms) [21/28] InvalidationClientImplTest.Register (7 ms) [ RUN ] InvalidationClientImplTest.Invalidations [26387:26387:0324/002439.223875:11875865265:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004730 with delay 0 [26387:26387:0324/002439.223947:11875865334:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.224291:11875865687:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004e10 with delay 0 [26387:26387:0324/002439.224338:11875865725:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004730 [26387:26387:0324/002439.224370:11875865756:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004e10 [26387:26387:0324/002439.224526:11875865912:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.224587:11875865974:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004ed0 with delay 0 [26387:26387:0324/002439.224650:11875866037:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004ed0 [26387:26387:0324/002439.224672:11875866058:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.224718:11875866106:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f10 with delay 0 [26387:26387:0324/002439.224748:11875866138:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004f10 [26387:26387:0324/002439.224777:11875866163:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.224809:11875866194:INFO:recurring-task.cc(55)] [Startup] Scheduling 72488 with a delay 0, Now = 210919424 [26387:26387:0324/002439.224836:11875866222:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f30 with delay 0 [26387:26387:0324/002439.224866:11875866253:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004f30 [26387:26387:0324/002439.224924:11875866310:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-67671502209032569" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.225002:11875866389:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 72744 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.225032:11875866420:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f50 with delay 500 [26387:26387:0324/002439.225100:11875866486:INFO:recurring-task.cc(55)] [Retry] Scheduling 72488 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.225126:11875866513:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f70 with delay 60000 [26387:26387:0324/002439.225165:11875866552:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004f50 [26387:26387:0324/002439.225191:11875866587:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.225245:11875866632:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.225501:11875866889: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: "-67671502209032569" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.225630:11875867018:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005010 with delay 0 [26387:26387:0324/002439.225690:11875867078:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005010 [26387:26387:0324/002439.225818:11875867205:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-67671502209032569" 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" } } [26387:26387:0324/002439.225873:11875867262:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-67671502209032569" [26387:26387:0324/002439.225906:11875867295:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.225939:11875867327:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20488 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.225970:11875867358:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005030 with delay 1200000 [26387:26387:0324/002439.226005:11875867391:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.226238:11875867625:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.226278:11875867666:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 14664 with a delay 0, Now = 211419424 [26387:26387:0324/002439.226322:11875867709:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005250 with delay 0 [26387:26387:0324/002439.226373:11875867759: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 [26387:26387:0324/002439.226408:11875867795:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005250 [26387:26387:0324/002439.226481:11875867868:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005310 with delay 0 [26387:26387:0324/002439.226545:11875867933:INFO:recurring-task.cc(55)] [Retry] Scheduling 14664 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.226594:11875867981:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005350 with delay 10000 [26387:26387:0324/002439.226620:11875868023:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005310 [26387:26387:0324/002439.226661:11875868049:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.226735:11875868122:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.226786:11875868173:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000005370 with delay 0 [26387:26387:0324/002439.226812:11875868200:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000005370 [26387:26387:0324/002439.227020:11875868409: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 } } } [26387:26387:0324/002439.227116:11875868504: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 [26387:26387:0324/002439.227255:11875868643: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" } [26387:26387:0324/002439.227410:11875868798:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [26387:26387:0324/002439.227497:11875868883:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [26387:26387:0324/002439.227591:11875868979:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000005750 with delay 0 [26387:26387:0324/002439.227624:11875869011:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000005770 with delay 0 [26387:26387:0324/002439.227649:11875869034:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000005790 with delay 0 [26387:26387:0324/002439.227677:11875869063:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000005750 [26387:26387:0324/002439.227720:11875869107:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 72744 with a delay 500000, Now = 211519424 [26387:26387:0324/002439.227753:11875869139:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x6020000057b0 with delay 500 [26387:26387:0324/002439.227781:11875869168:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000005770 [26387:26387:0324/002439.227807:11875869192:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000005790 [26387:26387:0324/002439.227859:11875869246:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x6020000057b0 [26387:26387:0324/002439.227889:11875869276:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.227941:11875869328:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.227970:11875869357:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [26387:26387:0324/002439.228136:11875869522:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: "2" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } } [ OK ] InvalidationClientImplTest.Invalidations (5 ms) [22/28] InvalidationClientImplTest.Invalidations (5 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [26387:26387:0324/002439.228863:11875870252:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006090 with delay 0 [26387:26387:0324/002439.228912:11875870298:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.229123:11875870510:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000065b0 with delay 0 [26387:26387:0324/002439.229154:11875870543:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006090 [26387:26387:0324/002439.229184:11875870570:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000065b0 [26387:26387:0324/002439.229235:11875870621:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.229286:11875870685:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006670 with delay 0 [26387:26387:0324/002439.229353:11875870740:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006670 [26387:26387:0324/002439.229383:11875870770:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.229414:11875870801:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066b0 with delay 0 [26387:26387:0324/002439.229440:11875870825:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000066b0 [26387:26387:0324/002439.229460:11875870846:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.229493:11875870881:INFO:recurring-task.cc(55)] [Startup] Scheduling 102184 with a delay 0, Now = 210919424 [26387:26387:0324/002439.229534:11875870922:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066d0 with delay 0 [26387:26387:0324/002439.229559:11875870945:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000066d0 [26387:26387:0324/002439.229633:11875871020:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4597122783599463388" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.229678:11875871065:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 102440 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.229704:11875871094:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066f0 with delay 500 [26387:26387:0324/002439.229732:11875871119:INFO:recurring-task.cc(55)] [Retry] Scheduling 102184 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.229766:11875871153:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006710 with delay 60000 [26387:26387:0324/002439.229812:11875871197:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000066f0 [26387:26387:0324/002439.229836:11875871222:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.229883:11875871270:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.230004:11875871391: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: "-4597122783599463388" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.230107:11875871493:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000067b0 with delay 0 [26387:26387:0324/002439.230135:11875871521:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000067b0 [26387:26387:0324/002439.230240:11875871627:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4597122783599463388" 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" } } [26387:26387:0324/002439.230388:11875871777:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4597122783599463388" [26387:26387:0324/002439.230420:11875871807:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.230453:11875871840:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 24536 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.230480:11875871867:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000067d0 with delay 1200000 [26387:26387:0324/002439.230527:11875871914:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.230691:11875872078:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.230728:11875872114:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 20808 with a delay 0, Now = 211419424 [26387:26387:0324/002439.230758:11875872144:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000069f0 with delay 0 [26387:26387:0324/002439.230803:11875872190: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 [26387:26387:0324/002439.230838:11875872232:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000069f0 [26387:26387:0324/002439.230912:11875872300:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006ab0 with delay 0 [26387:26387:0324/002439.230949:11875872335:INFO:recurring-task.cc(55)] [Retry] Scheduling 20808 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.231019:11875872406:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006af0 with delay 10000 [26387:26387:0324/002439.231048:11875872435:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006ab0 [26387:26387:0324/002439.231072:11875872466:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.231125:11875872512:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.231185:11875872572:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006b10 with delay 0 [26387:26387:0324/002439.231258:11875872645:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006b10 [26387:26387:0324/002439.231383:11875872770: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 } } [26387:26387:0324/002439.231477:11875872865: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 [26387:26387:0324/002439.231522:11875872909:INFO:protocol-handler.cc(294)] Adding subtree: { } [26387:26387:0324/002439.231558:11875872944:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 102440 with a delay 500000, Now = 211469424 [26387:26387:0324/002439.231595:11875872982:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006b30 with delay 500 [26387:26387:0324/002439.231621:11875873007:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [26387:26387:0324/002439.231850:11875873238: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 } [26387:26387:0324/002439.231958:11875873345:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000006b30 [26387:26387:0324/002439.231991:11875873377:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.232135:11875873522:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.232168:11875873555:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [26387:26387:0324/002439.232539:11875873928: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 } } [26387:26387:0324/002439.232867:11875874254:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000006af0 [ OK ] InvalidationClientImplTest.ServerRequests (6 ms) [23/28] InvalidationClientImplTest.ServerRequests (6 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [26387:26387:0324/002439.234454:11875875843:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007410 with delay 0 [26387:26387:0324/002439.234512:11875875899:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.234950:11875876339:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000079d0 with delay 0 [26387:26387:0324/002439.234990:11875876376:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007410 [26387:26387:0324/002439.235016:11875876401:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000079d0 [26387:26387:0324/002439.235066:11875876453:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.235122:11875876509:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007a90 with delay 0 [26387:26387:0324/002439.235155:11875876542:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007a90 [26387:26387:0324/002439.235178:11875876564:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.235218:11875876606:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007ad0 with delay 0 [26387:26387:0324/002439.235249:11875876636:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007ad0 [26387:26387:0324/002439.235282:11875876669:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.235325:11875876712:INFO:recurring-task.cc(55)] [Startup] Scheduling 129448 with a delay 0, Now = 210919424 [26387:26387:0324/002439.235355:11875876742:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007af0 with delay 0 [26387:26387:0324/002439.235390:11875876776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007af0 [26387:26387:0324/002439.235443:11875876830:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6268692181103745829" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.235472:11875876859:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 129704 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.235500:11875876887:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007b10 with delay 500 [26387:26387:0324/002439.235531:11875876916:INFO:recurring-task.cc(55)] [Retry] Scheduling 129448 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.235555:11875876941:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007b30 with delay 60000 [26387:26387:0324/002439.235603:11875876989:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007b10 [26387:26387:0324/002439.235630:11875877017:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.235794:11875877190:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.235945:11875877332: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: "-6268692181103745829" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.236050:11875877438:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007bd0 with delay 0 [26387:26387:0324/002439.236090:11875877477:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007bd0 [26387:26387:0324/002439.236193:11875877579:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6268692181103745829" 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" } } [26387:26387:0324/002439.236252:11875877638:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6268692181103745829" [26387:26387:0324/002439.236278:11875877664:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.236324:11875877710:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28056 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.236354:11875877741:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007bf0 with delay 1200000 [26387:26387:0324/002439.236388:11875877775:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.236586:11875877974:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.236632:11875878018:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 26184 with a delay 0, Now = 211419424 [26387:26387:0324/002439.236665:11875878051:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007e10 with delay 0 [26387:26387:0324/002439.236713:11875878100: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 [26387:26387:0324/002439.236748:11875878134:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007e10 [26387:26387:0324/002439.236833:11875878220:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007ed0 with delay 0 [26387:26387:0324/002439.236867:11875878253:INFO:recurring-task.cc(55)] [Retry] Scheduling 26184 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.236905:11875878330:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007f10 with delay 10000 [26387:26387:0324/002439.236971:11875878357:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007ed0 [26387:26387:0324/002439.237000:11875878388:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.237046:11875878432:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.237089:11875878483:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007f30 with delay 0 [26387:26387:0324/002439.237126:11875878513:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000007f30 [26387:26387:0324/002439.237260:11875878647: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" } } [26387:26387:0324/002439.237350:11875878738: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 [26387:26387:0324/002439.237378:11875878765:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [26387:26387:0324/002439.237737:11875879126:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000007f10 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [26387:26387:0324/002439.239247:11875880636:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008890 with delay 0 [26387:26387:0324/002439.239430:11875880816:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.239744:11875881132:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f10 with delay 0 [26387:26387:0324/002439.239790:11875881177:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008890 [26387:26387:0324/002439.239823:11875881210:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008f10 [26387:26387:0324/002439.239875:11875881263:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.239932:11875881317:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008fd0 with delay 0 [26387:26387:0324/002439.239974:11875881362:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008fd0 [26387:26387:0324/002439.239998:11875881385:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.240037:11875881424:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009010 with delay 0 [26387:26387:0324/002439.240078:11875881468:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009010 [26387:26387:0324/002439.240106:11875881492:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.240135:11875881522:INFO:recurring-task.cc(55)] [Startup] Scheduling 152104 with a delay 0, Now = 210919424 [26387:26387:0324/002439.240170:11875881556:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009030 with delay 0 [26387:26387:0324/002439.240196:11875881582:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009030 [26387:26387:0324/002439.240246:11875881641:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "4046813157218136471" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.240311:11875881697:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 152360 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.240395:11875881782:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009050 with delay 500 [26387:26387:0324/002439.240440:11875881827:INFO:recurring-task.cc(55)] [Retry] Scheduling 152104 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.240472:11875881859:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009070 with delay 60000 [26387:26387:0324/002439.240514:11875881899:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009050 [26387:26387:0324/002439.240537:11875881925:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.240576:11875881973:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.240725:11875882112: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: "4046813157218136471" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.240888:11875882276:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009110 with delay 0 [26387:26387:0324/002439.240923:11875882310:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009110 [26387:26387:0324/002439.241117:11875882505:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "4046813157218136471" 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" } } [26387:26387:0324/002439.241169:11875882556:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "4046813157218136471" [26387:26387:0324/002439.241203:11875882589:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.241249:11875882636:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31224 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.241292:11875882688:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009130 with delay 1200000 [26387:26387:0324/002439.241332:11875882718:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.241488:11875882876:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.241532:11875882918:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 29832 with a delay 0, Now = 211419424 [26387:26387:0324/002439.241566:11875882953:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009350 with delay 0 [26387:26387:0324/002439.241624:11875883010: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 [26387:26387:0324/002439.241660:11875883047:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009350 [26387:26387:0324/002439.241737:11875883123:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009410 with delay 0 [26387:26387:0324/002439.241856:11875883244:INFO:recurring-task.cc(55)] [Retry] Scheduling 29832 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.241886:11875883272:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009450 with delay 10000 [26387:26387:0324/002439.241915:11875883300:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009410 [26387:26387:0324/002439.241936:11875883322:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.241977:11875883364:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009470 with delay 0 [26387:26387:0324/002439.242013:11875883401:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000009470 [26387:26387:0324/002439.242051:11875883437:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [26387:26387:0324/002439.242129:11875883516:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 152360 with a delay 500000, Now = 211469424 [26387:26387:0324/002439.242166:11875883553:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009490 with delay 500 [26387:26387:0324/002439.242212:11875883599:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 152232 with a delay 60000000, Now = 211469424 [26387:26387:0324/002439.242242:11875883629:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000094b0 with delay 60000 [26387:26387:0324/002439.242284:11875883670:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009490 [26387:26387:0324/002439.242319:11875883707:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.242386:11875883773:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.242412:11875883797:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [26387:26387:0324/002439.242544:11875883931: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 } } } [26387:26387:0324/002439.242661:11875884047:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.242706:11875884093:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000009550 with delay 0 [26387:26387:0324/002439.242736:11875884124:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009550 [26387:26387:0324/002439.242907:11875884294: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" } } [26387:26387:0324/002439.243008:11875884402: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 [26387:26387:0324/002439.243053:11875884439:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [26387:26387:0324/002439.243146:11875884532:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [26387:26387:0324/002439.243476:11875884863:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000009450 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [26387:26387:0324/002439.244858:11875886246:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009fb0 with delay 0 [26387:26387:0324/002439.244904:11875886290:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.245251:11875886638:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a4d0 with delay 0 [26387:26387:0324/002439.245286:11875886673:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009fb0 [26387:26387:0324/002439.245326:11875886713:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a4d0 [26387:26387:0324/002439.245375:11875886762:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.245442:11875886829:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a590 with delay 0 [26387:26387:0324/002439.245477:11875886864:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a590 [26387:26387:0324/002439.245508:11875886894:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.245537:11875886924:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a5d0 with delay 0 [26387:26387:0324/002439.245565:11875886952:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a5d0 [26387:26387:0324/002439.245606:11875886992:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.245634:11875887022:INFO:recurring-task.cc(55)] [Startup] Scheduling 180520 with a delay 0, Now = 210919424 [26387:26387:0324/002439.245671:11875887058:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a5f0 with delay 0 [26387:26387:0324/002439.245699:11875887086:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a5f0 [26387:26387:0324/002439.245747:11875887136:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1036695704509966696" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.245778:11875887165:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 180776 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.245807:11875887194:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a610 with delay 500 [26387:26387:0324/002439.245832:11875887222:INFO:recurring-task.cc(55)] [Retry] Scheduling 180520 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.245865:11875887253:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a630 with delay 60000 [26387:26387:0324/002439.245911:11875887296:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a610 [26387:26387:0324/002439.245946:11875887333:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.246007:11875887393:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.246243:11875887632: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: "1036695704509966696" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.246374:11875887765:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a6d0 with delay 0 [26387:26387:0324/002439.246404:11875887793:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a6d0 [26387:26387:0324/002439.246522:11875887909:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1036695704509966696" 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" } } [26387:26387:0324/002439.246572:11875887958:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1036695704509966696" [26387:26387:0324/002439.246720:11875888108:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.246754:11875888141:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 34568 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.246787:11875888173:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a6f0 with delay 1200000 [26387:26387:0324/002439.246815:11875888203:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.246953:11875888341:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.247089:11875888476:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 35208 with a delay 0, Now = 211419424 [26387:26387:0324/002439.247121:11875888508:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a910 with delay 0 [26387:26387:0324/002439.247165:11875888551: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 [26387:26387:0324/002439.247198:11875888585:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a910 [26387:26387:0324/002439.247256:11875888642:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a9d0 with delay 0 [26387:26387:0324/002439.247304:11875888691:INFO:recurring-task.cc(55)] [Retry] Scheduling 35208 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.247329:11875888715:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000aa10 with delay 10000 [26387:26387:0324/002439.247357:11875888743:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a9d0 [26387:26387:0324/002439.247405:11875888791:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.247485:11875888871:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000aa30 with delay 0 [26387:26387:0324/002439.247516:11875888904:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000aa30 [26387:26387:0324/002439.247556:11875888942:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [26387:26387:0324/002439.247609:11875888997:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 180776 with a delay 500000, Now = 211469424 [26387:26387:0324/002439.247639:11875889025:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000aa50 with delay 500 [26387:26387:0324/002439.247665:11875889059:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 180648 with a delay 60000000, Now = 211469424 [26387:26387:0324/002439.247715:11875889102:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000aa70 with delay 60000 [26387:26387:0324/002439.247759:11875889144:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000aa50 [26387:26387:0324/002439.247781:11875889172:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.247823:11875889210:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.247847:11875889235:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [26387:26387:0324/002439.248091:11875889487: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 } } } [26387:26387:0324/002439.248383:11875889772:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000aa10 [26387:26387:0324/002439.249236:11875890623:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000a630 [26387:26387:0324/002439.249271:11875890656:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000aa70 [26387:26387:0324/002439.249325:11875890712: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 [26387:26387:0324/002439.249379:11875890766:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [26387:26387:0324/002439.249441:11875890831: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 } [26387:26387:0324/002439.249480:11875890866:INFO:recurring-task.cc(55)] [Send-info] Scheduling 180776 with a delay 500000, Now = 271469424 [26387:26387:0324/002439.249509:11875890895:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000ab10 with delay 500 [26387:26387:0324/002439.249538:11875890924:INFO:recurring-task.cc(55)] [Retry] Scheduling 180648 with a delay 60000000, Now = 271469424 [26387:26387:0324/002439.249567:11875890953:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000ab30 with delay 60000 [26387:26387:0324/002439.249611:11875890998:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000ab10 [26387:26387:0324/002439.249634:11875891021:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.249681:11875891067:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.249718:11875891106:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [26387:26387:0324/002439.249916:11875891302: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 [26387:26387:0324/002439.251671:11875893061:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b410 with delay 0 [26387:26387:0324/002439.251720:11875893107:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.251960:11875893349:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b930 with delay 0 [26387:26387:0324/002439.251993:11875893382:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b410 [26387:26387:0324/002439.252019:11875893405:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b930 [26387:26387:0324/002439.252075:11875893463:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.252140:11875893527:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b9f0 with delay 0 [26387:26387:0324/002439.252172:11875893559:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b9f0 [26387:26387:0324/002439.252193:11875893580:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.252222:11875893608:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba30 with delay 0 [26387:26387:0324/002439.252245:11875893632:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ba30 [26387:26387:0324/002439.252268:11875893658:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.252311:11875893697:INFO:recurring-task.cc(55)] [Startup] Scheduling 209448 with a delay 0, Now = 210919424 [26387:26387:0324/002439.252339:11875893725:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba50 with delay 0 [26387:26387:0324/002439.252486:11875893873:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ba50 [26387:26387:0324/002439.252538:11875893925:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3860020843696946788" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.252593:11875893980:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 209704 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.252620:11875894010:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba70 with delay 500 [26387:26387:0324/002439.252647:11875894036:INFO:recurring-task.cc(55)] [Retry] Scheduling 209448 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.252678:11875894064:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba90 with delay 60000 [26387:26387:0324/002439.252711:11875894098:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ba70 [26387:26387:0324/002439.252750:11875894137:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.252789:11875894176:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.252894:11875894281: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: "-3860020843696946788" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.253006:11875894394:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000bb30 with delay 0 [26387:26387:0324/002439.253037:11875894424:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000bb30 [26387:26387:0324/002439.253146:11875894532:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3860020843696946788" 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" } } [26387:26387:0324/002439.253192:11875894579:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3860020843696946788" [26387:26387:0324/002439.253226:11875894613:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.253367:11875894755:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 37208 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.253397:11875894785:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000bb50 with delay 1200000 [26387:26387:0324/002439.253490:11875894876:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.253625:11875895011:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.253662:11875895049:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 41160 with a delay 0, Now = 211419424 [26387:26387:0324/002439.253693:11875895080:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000bd70 with delay 0 [26387:26387:0324/002439.253736:11875895123: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 [26387:26387:0324/002439.253779:11875895165:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000bd70 [26387:26387:0324/002439.253837:11875895224:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000be30 with delay 0 [26387:26387:0324/002439.253884:11875895270:INFO:recurring-task.cc(55)] [Retry] Scheduling 41160 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.253913:11875895299:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000be70 with delay 10000 [26387:26387:0324/002439.253949:11875895336:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000be30 [26387:26387:0324/002439.253972:11875895357:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.254014:11875895401:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.254051:11875895437:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000be90 with delay 0 [26387:26387:0324/002439.254084:11875895472:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000be90 [26387:26387:0324/002439.254168:11875895555: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" } } [26387:26387:0324/002439.254404:11875895791:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000be70 [26387:26387:0324/002439.255200:11875896590: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 [26387:26387:0324/002439.255865:11875897253:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6f0 with delay 0 [26387:26387:0324/002439.255912:11875897300:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [26387:26387:0324/002439.256116:11875897504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cc10 with delay 0 [26387:26387:0324/002439.256149:11875897535:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6f0 [26387:26387:0324/002439.256178:11875897565:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cc10 [26387:26387:0324/002439.256282:11875897668:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [26387:26387:0324/002439.256350:11875897737:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ccd0 with delay 0 [26387:26387:0324/002439.256385:11875897771:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ccd0 [26387:26387:0324/002439.256408:11875897793:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [26387:26387:0324/002439.256440:11875897827:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd10 with delay 0 [26387:26387:0324/002439.256468:11875897856:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cd10 [26387:26387:0324/002439.256490:11875897875:INFO:invalidation-client-core.cc(351)] Starting with no previous state [26387:26387:0324/002439.256517:11875897904:INFO:recurring-task.cc(55)] [Startup] Scheduling 231080 with a delay 0, Now = 210919424 [26387:26387:0324/002439.256548:11875897935:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd30 with delay 0 [26387:26387:0324/002439.256729:11875898115:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cd30 [26387:26387:0324/002439.256799:11875898186:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1967271475143381497" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [26387:26387:0324/002439.256835:11875898222:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 231336 with a delay 500000, Now = 210919424 [26387:26387:0324/002439.256868:11875898255:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd50 with delay 500 [26387:26387:0324/002439.256893:11875898279:INFO:recurring-task.cc(55)] [Retry] Scheduling 231080 with a delay 60000000, Now = 210919424 [26387:26387:0324/002439.256931:11875898318:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd70 with delay 60000 [26387:26387:0324/002439.256969:11875898355:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cd50 [26387:26387:0324/002439.256999:11875898385:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.257041:11875898427:INFO:invalidation-client-core.cc(488)] Return client token = "" [26387:26387:0324/002439.257150:11875898537: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: "1967271475143381497" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [26387:26387:0324/002439.257303:11875898691:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ce10 with delay 0 [26387:26387:0324/002439.257339:11875898725:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ce10 [26387:26387:0324/002439.257495:11875898881:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1967271475143381497" 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" } } [26387:26387:0324/002439.257558:11875898948:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1967271475143381497" [26387:26387:0324/002439.257606:11875898992:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [26387:26387:0324/002439.257641:11875899028:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 39672 with a delay 1200000000, Now = 211419424 [26387:26387:0324/002439.257679:11875899066:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ce30 with delay 1200000 [26387:26387:0324/002439.257713:11875899102:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [26387:26387:0324/002439.257844:11875899232:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.257878:11875899264:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 44808 with a delay 0, Now = 211419424 [26387:26387:0324/002439.257909:11875899295:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d050 with delay 0 [26387:26387:0324/002439.257955:11875899341: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 [26387:26387:0324/002439.258000:11875899386:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d050 [26387:26387:0324/002439.258059:11875899445:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d110 with delay 0 [26387:26387:0324/002439.258102:11875899487:INFO:recurring-task.cc(55)] [Retry] Scheduling 44808 with a delay 10000000, Now = 211419424 [26387:26387:0324/002439.258128:11875899515:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d150 with delay 10000 [26387:26387:0324/002439.258156:11875899542:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d110 [26387:26387:0324/002439.258189:11875899575:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [26387:26387:0324/002439.258510:11875899898:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000d150 [26387:26387:0324/002439.259393:11875900781:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000cd70 [26387:26387:0324/002439.278991:11875920391:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000ce30 [26387:26387:0324/002439.279091:11875920478:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.279156:11875920543:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [26387:26387:0324/002439.279194:11875920580:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [26387:26387:0324/002439.279457:11875920848: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 } [26387:26387:0324/002439.279532:11875920920:INFO:recurring-task.cc(55)] [Send-info] Scheduling 231336 with a delay 500000, Now = 1411419424 [26387:26387:0324/002439.279587:11875920974:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000d170 with delay 500 [26387:26387:0324/002439.279622:11875921009:INFO:recurring-task.cc(55)] [Retry] Scheduling 39672 with a delay 1200000000, Now = 1411419424 [26387:26387:0324/002439.279652:11875921040:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000d190 with delay 1200000 [26387:26387:0324/002439.279691:11875921077:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000d170 [26387:26387:0324/002439.279723:11875921110:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.279804:11875921191:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [26387:26387:0324/002439.279831:11875921217:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [26387:26387:0324/002439.280120:11875921516: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-24 12:15:37,790 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmp0m9HoQ/43c9ee43dc0b8a10'] 2019-03-24 12:15:37,791 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmp0m9HoQ/43c9ee43dc0b8a10/output.json'] 2019-03-24 12:15:37,791 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"bot_id": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553454418169658, "id": "8918078695972117904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32287", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/24025d13a3d457e28cdbe59dc91e73222da3af1f", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44245", "scheduler_invocation_id:9083508758827879456", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32287, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "got_revision_cp": "refs/heads/master@{#643731}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "parent_got_revision_cp": "refs/heads/master@{#643731}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "swarm_hashes": {"accessibility_unittests": "e64b88bcbe1179f6d81f7362bec9d96500d520be", "angle_unittests": "8fa699180f64cc4627ea447ae53881dfd5a034af", "app_list_unittests": "02dfd89c154f0ae7a82ea0b7b68c4b0be571ef73", "app_shell_unittests": "73777bed4cba13bb28f4a7d238edab673566b75d", "ash_unittests": "71c06c977f3ddecdb74fd12661d242474288a023", "aura_unittests": "1b9e5dc39de4c717df48498790cdf12b15fb781b", "base_unittests": "9ba9ecb6397bc5bed5b74500b6f24971bdcff0d5", "blink_common_unittests": "823cae7dfe14609028b63870c4b96b24a0fdde88", "blink_fuzzer_unittests": "712e5000a70c39da2e906e66c66b1167aa65e653", "blink_heap_unittests": "d10d2e28509448b149e46e26a0238d9b70dcc555", "blink_platform_unittests": "9ad52b8e8746b870817252b592d55b5d36438ce5", "blink_unittests": "d9c80f0734c0dfc55f5692d012432cd36a78a423", "boringssl_crypto_tests": "f6fdd625df20aec1de05caea9eaff99624324db7", "boringssl_ssl_tests": "812ad09c691f6e5e77f0c609a7fde5ab83766887", "browser_tests": "609023ce3961c8df58a7c4ef7acde88153923785", "cacheinvalidation_unittests": "f5b8c2a16c5703e95b45e1611e972a42e4745c49", "capture_unittests": "e9f97f6ca3f90e7bf7b4bd07341b09db08c92f7d", "cast_unittests": "30d02dc5332b66aee36944938c9d8051b3a67aea", "cc_unittests": "5fd296bf750f9477cfee6a2d2ede98f789b1d84e", "chrome_app_unittests": "dfd553a30ceb86cd08ac4d11fd022ce26307f01a", "chromedriver_unittests": "54e2974eaa37cd52a213cc87cac9cd540ed43302", "chromeos_components_unittests": "750480a2563dd293370eebefc400d06280c8daac", "chromeos_unittests": "446839e3944954709f088e0de729f5fd18432f57", "components_browsertests": "666ee63506e175358d3faa5dea6aabb4e0a5e43a", "components_unittests": "139ab46c3afd42cd3c2e4c1e82b587ae84142c2e", "compositor_unittests": "0817c123a43f8f1099aae83ef34d90f873a56325", "content_browsertests": "ee7334ebb986f5f0cd857916aab0e4f7de0ee729", "content_unittests": "6aafc4ea763dfb1381c02f12cddb600e0cde0643", "crypto_unittests": "bda07e809950bad650f7bb959fd6e32fd06837ea", "dbus_unittests": "e0e6adbf24f46347b2eea8daae7257f215d9f307", "device_unittests": "c4794958338778463ccc0f69d19031c1593f8b9f", "display_unittests": "707228d56b71f0d77c0cbf192a01fafd97cadc4c", "events_unittests": "253bdab2bde8e77e14a74094f9225ff71d10417f", "exo_unittests": "74c47884c09aca11a207d4e376178ded43ae820e", "extensions_browsertests": "63dcd7c85eee8b2dcbcbb8d8028ab41a68927000", "extensions_unittests": "c6306fab457ffb23d7293663911a66f7afed0d6a", "filesystem_service_unittests": "29b1744b158e73e980a83e61a0049fba28cdce4d", "gcm_unit_tests": "bc0ce5e5f1d992f7db7c820eedc3d00d915e0937", "gfx_unittests": "e094f212a05ad9cb7ac2dc23f09d1fdffd0e6092", "gl_unittests_ozone": "c49b99e7d6c70746d1e09024933e112eb32adb35", "google_apis_unittests": "76bbdbbe5e3fd4ef5b8be4d2548a53c3c4054c8f", "gpu_unittests": "1229541f3884f792fdb08d179da79ad491355111", "interactive_ui_tests": "5cee9610508ce8f7992acb9f95a8751825fb60f3", "ipc_tests": "6c2011b2aefd70eea3dc896b535b3783cc29645e", "jingle_unittests": "50068a1a2c508cbcb908d44fb3b67c0ea56c5c85", "keyboard_unittests": "b7ea2e90dd1d1a9b77d3264c6fbd5576e65a692f", "latency_unittests": "0748e6338a4de70a5fc1fdbf4c45945b1608b545", "leveldb_service_unittests": "97879d672b0babd91397319a70b94998d9c94c18", "libjingle_xmpp_unittests": "45db1df7828a48e33cc02882dca6525f59220997", "media_blink_unittests": "aec5bd53c36ef67ae7918abf9d566e9d0247d4e7", "media_service_unittests": "dd1e477f5d78f22e5797973893d05df67cebd27a", "media_unittests": "3bc32a8830e7cbf60dbbae637705a878b5e67469", "message_center_unittests": "35e6c4683f17977e9276d49d630e963ea23eb0c2", "midi_unittests": "6171f1bd07632ac259259dcd2eb7606f7036733a", "mojo_core_unittests": "e56c8c4a3154c072c5cc8b2985973b66450a9a75", "mojo_unittests": "1d5e40b04cffe375e15bf7c2dcd20d1ef9d759cc", "nacl_helper_nonsfi_unittests": "c84ff16e368053268ff6f5a34881019c9e45d02b", "nacl_loader_unittests": "c3243886c503904b3bacf60cf76f1bf60b7186d9", "native_theme_unittests": "86a7643e5ff1e180b8a34dab91c73d128237261f", "net_unittests": "82baf73a24b292aa1b0cce9c9307e9eabbba18f2", "ozone_gl_unittests": "94872d0292c59a8cee50b4fab5ba084964eba34c", "ozone_unittests": "cc2e56782215e8a62da2078d0fd6c4841224e531", "ozone_x11_unittests": "d3b60c43ddf4c3c396c64eef166fa2c2d22bf991", "pdf_unittests": "4fdb74d082859f50d720cf576182dc50c2f8195b", "perfetto_unittests": "5d8c491c19c3ad4b1daeccf129f71a2bd76296ee", "ppapi_unittests": "11a2e33db41121e102fe6ef1fa8bc3ed0ae1c062", "printing_unittests": "1fe4efcf41a9000303704a209d861e8d743e9b71", "remoting_unittests": "d665c9b8faced5300a7533cffaa6429d9d4d4123", "sandbox_linux_unittests": "e4d1ad8374c33b847b8b152c3dcc9ca6460b9258", "service_manager_unittests": "48a9529c8e12243154f1157cabcced59e245212d", "services_unittests": "a0bfb13fe742a512c91308b5fe5aca42693af384", "shell_dialogs_unittests": "eab64e7bacea6e74780ab6c02a29d0e8c395c603", "skia_unittests": "2c8b235d87bd7fdac84b5a08afc867685b6417ff", "snapshot_unittests": "44a4a0e75988af52a03f63bf09d67fd66f597bf7", "sql_unittests": "4229bc5954144b61acac98a41d4a68090715f108", "storage_unittests": "a75e190f5d9531963eac4603f9d548e9b62e8814", "sync_integration_tests": "82adff571f088b812b692726564d052c72780763", "traffic_annotation_auditor_unittests": "26e49645f979d46bffb1150017e0e0918d59ce49", "ui_base_unittests": "eedbaea22c4ced7255de07eb534378f13fd82169", "ui_chromeos_unittests": "db62467aa3a708637ad388f6d8bc2c4c7f579949", "ui_touch_selection_unittests": "1fa57521330981c93a8e50bf535e366c45a5f9c5", "unit_tests": "bc4483b81e5fe3cbe2bc3afcdbcbf3cc125c7fa4", "url_unittests": "63bf0ac3962e57d89e9ee9d002342e06ac55ba66", "usage_time_limit_unittests": "815ea1bd8d3d8bc0a0b09368c7a9a278f2014dce", "views_unittests": "a29ec6cd2a1af6b5ab4679e90c9cf4977d7bb80d", "viz_unittests": "3b1558a6e2ea9927303f270d53f20fdab15833f9", "wayland_client_perftests": "255db5d049e103f0474ea814131278a3aa30c8b6", "wm_unittests": "d0b438227fba5194322231fd77e153acad8bbfa4", "wtf_unittests": "ba23313940818e93b11b06fa2a3ab7624c6391cd"}} --summary-json /b/swarming/w/ir/tmp/t/tmpcseQNW.json --task-output-dir /b/swarming/w/ir/tmp/t/tmp0m9HoQ -o /b/swarming/w/ir/tmp/t/tmpjLnm_H.json /b/swarming/w/ir/tmp/t/tmp0m9HoQ/43c9ee43dc0b8a10/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553454418169658, "id": "8918078695972117904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32287", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/24025d13a3d457e28cdbe59dc91e73222da3af1f", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44245", "scheduler_invocation_id:9083508758827879456", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32287, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "got_revision_cp": "refs/heads/master@{#643731}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "parent_got_revision_cp": "refs/heads/master@{#643731}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "swarm_hashes": {"accessibility_unittests": "e64b88bcbe1179f6d81f7362bec9d96500d520be", "angle_unittests": "8fa699180f64cc4627ea447ae53881dfd5a034af", "app_list_unittests": "02dfd89c154f0ae7a82ea0b7b68c4b0be571ef73", "app_shell_unittests": "73777bed4cba13bb28f4a7d238edab673566b75d", "ash_unittests": "71c06c977f3ddecdb74fd12661d242474288a023", "aura_unittests": "1b9e5dc39de4c717df48498790cdf12b15fb781b", "base_unittests": "9ba9ecb6397bc5bed5b74500b6f24971bdcff0d5", "blink_common_unittests": "823cae7dfe14609028b63870c4b96b24a0fdde88", "blink_fuzzer_unittests": "712e5000a70c39da2e906e66c66b1167aa65e653", "blink_heap_unittests": "d10d2e28509448b149e46e26a0238d9b70dcc555", "blink_platform_unittests": "9ad52b8e8746b870817252b592d55b5d36438ce5", "blink_unittests": "d9c80f0734c0dfc55f5692d012432cd36a78a423", "boringssl_crypto_tests": "f6fdd625df20aec1de05caea9eaff99624324db7", "boringssl_ssl_tests": "812ad09c691f6e5e77f0c609a7fde5ab83766887", "browser_tests": "609023ce3961c8df58a7c4ef7acde88153923785", "cacheinvalidation_unittests": "f5b8c2a16c5703e95b45e1611e972a42e4745c49", "capture_unittests": "e9f97f6ca3f90e7bf7b4bd07341b09db08c92f7d", "cast_unittests": "30d02dc5332b66aee36944938c9d8051b3a67aea", "cc_unittests": "5fd296bf750f9477cfee6a2d2ede98f789b1d84e", "chrome_app_unittests": "dfd553a30ceb86cd08ac4d11fd022ce26307f01a", "chromedriver_unittests": "54e2974eaa37cd52a213cc87cac9cd540ed43302", "chromeos_components_unittests": "750480a2563dd293370eebefc400d06280c8daac", "chromeos_unittests": "446839e3944954709f088e0de729f5fd18432f57", "components_browsertests": "666ee63506e175358d3faa5dea6aabb4e0a5e43a", "components_unittests": "139ab46c3afd42cd3c2e4c1e82b587ae84142c2e", "compositor_unittests": "0817c123a43f8f1099aae83ef34d90f873a56325", "content_browsertests": "ee7334ebb986f5f0cd857916aab0e4f7de0ee729", "content_unittests": "6aafc4ea763dfb1381c02f12cddb600e0cde0643", "crypto_unittests": "bda07e809950bad650f7bb959fd6e32fd06837ea", "dbus_unittests": "e0e6adbf24f46347b2eea8daae7257f215d9f307", "device_unittests": "c4794958338778463ccc0f69d19031c1593f8b9f", "display_unittests": "707228d56b71f0d77c0cbf192a01fafd97cadc4c", "events_unittests": "253bdab2bde8e77e14a74094f9225ff71d10417f", "exo_unittests": "74c47884c09aca11a207d4e376178ded43ae820e", "extensions_browsertests": "63dcd7c85eee8b2dcbcbb8d8028ab41a68927000", "extensions_unittests": "c6306fab457ffb23d7293663911a66f7afed0d6a", "filesystem_service_unittests": "29b1744b158e73e980a83e61a0049fba28cdce4d", "gcm_unit_tests": "bc0ce5e5f1d992f7db7c820eedc3d00d915e0937", "gfx_unittests": "e094f212a05ad9cb7ac2dc23f09d1fdffd0e6092", "gl_unittests_ozone": "c49b99e7d6c70746d1e09024933e112eb32adb35", "google_apis_unittests": "76bbdbbe5e3fd4ef5b8be4d2548a53c3c4054c8f", "gpu_unittests": "1229541f3884f792fdb08d179da79ad491355111", "interactive_ui_tests": "5cee9610508ce8f7992acb9f95a8751825fb60f3", "ipc_tests": "6c2011b2aefd70eea3dc896b535b3783cc29645e", "jingle_unittests": "50068a1a2c508cbcb908d44fb3b67c0ea56c5c85", "keyboard_unittests": "b7ea2e90dd1d1a9b77d3264c6fbd5576e65a692f", "latency_unittests": "0748e6338a4de70a5fc1fdbf4c45945b1608b545", "leveldb_service_unittests": "97879d672b0babd91397319a70b94998d9c94c18", "libjingle_xmpp_unittests": "45db1df7828a48e33cc02882dca6525f59220997", "media_blink_unittests": "aec5bd53c36ef67ae7918abf9d566e9d0247d4e7", "media_service_unittests": "dd1e477f5d78f22e5797973893d05df67cebd27a", "media_unittests": "3bc32a8830e7cbf60dbbae637705a878b5e67469", "message_center_unittests": "35e6c4683f17977e9276d49d630e963ea23eb0c2", "midi_unittests": "6171f1bd07632ac259259dcd2eb7606f7036733a", "mojo_core_unittests": "e56c8c4a3154c072c5cc8b2985973b66450a9a75", "mojo_unittests": "1d5e40b04cffe375e15bf7c2dcd20d1ef9d759cc", "nacl_helper_nonsfi_unittests": "c84ff16e368053268ff6f5a34881019c9e45d02b", "nacl_loader_unittests": "c3243886c503904b3bacf60cf76f1bf60b7186d9", "native_theme_unittests": "86a7643e5ff1e180b8a34dab91c73d128237261f", "net_unittests": "82baf73a24b292aa1b0cce9c9307e9eabbba18f2", "ozone_gl_unittests": "94872d0292c59a8cee50b4fab5ba084964eba34c", "ozone_unittests": "cc2e56782215e8a62da2078d0fd6c4841224e531", "ozone_x11_unittests": "d3b60c43ddf4c3c396c64eef166fa2c2d22bf991", "pdf_unittests": "4fdb74d082859f50d720cf576182dc50c2f8195b", "perfetto_unittests": "5d8c491c19c3ad4b1daeccf129f71a2bd76296ee", "ppapi_unittests": "11a2e33db41121e102fe6ef1fa8bc3ed0ae1c062", "printing_unittests": "1fe4efcf41a9000303704a209d861e8d743e9b71", "remoting_unittests": "d665c9b8faced5300a7533cffaa6429d9d4d4123", "sandbox_linux_unittests": "e4d1ad8374c33b847b8b152c3dcc9ca6460b9258", "service_manager_unittests": "48a9529c8e12243154f1157cabcced59e245212d", "services_unittests": "a0bfb13fe742a512c91308b5fe5aca42693af384", "shell_dialogs_unittests": "eab64e7bacea6e74780ab6c02a29d0e8c395c603", "skia_unittests": "2c8b235d87bd7fdac84b5a08afc867685b6417ff", "snapshot_unittests": "44a4a0e75988af52a03f63bf09d67fd66f597bf7", "sql_unittests": "4229bc5954144b61acac98a41d4a68090715f108", "storage_unittests": "a75e190f5d9531963eac4603f9d548e9b62e8814", "sync_integration_tests": "82adff571f088b812b692726564d052c72780763", "traffic_annotation_auditor_unittests": "26e49645f979d46bffb1150017e0e0918d59ce49", "ui_base_unittests": "eedbaea22c4ced7255de07eb534378f13fd82169", "ui_chromeos_unittests": "db62467aa3a708637ad388f6d8bc2c4c7f579949", "ui_touch_selection_unittests": "1fa57521330981c93a8e50bf535e366c45a5f9c5", "unit_tests": "bc4483b81e5fe3cbe2bc3afcdbcbf3cc125c7fa4", "url_unittests": "63bf0ac3962e57d89e9ee9d002342e06ac55ba66", "usage_time_limit_unittests": "815ea1bd8d3d8bc0a0b09368c7a9a278f2014dce", "views_unittests": "a29ec6cd2a1af6b5ab4679e90c9cf4977d7bb80d", "viz_unittests": "3b1558a6e2ea9927303f270d53f20fdab15833f9", "wayland_client_perftests": "255db5d049e103f0474ea814131278a3aa30c8b6", "wm_unittests": "d0b438227fba5194322231fd77e153acad8bbfa4", "wtf_unittests": "ba23313940818e93b11b06fa2a3ab7624c6391cd"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpcseQNW.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp0m9HoQ', '-o', '/b/swarming/w/ir/tmp/t/tmpjLnm_H.json', '/b/swarming/w/ir/tmp/t/tmp0m9HoQ/43c9ee43dc0b8a10/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553454418169658, "id": "8918078695972117904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32287", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/24025d13a3d457e28cdbe59dc91e73222da3af1f", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44245", "scheduler_invocation_id:9083508758827879456", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32287, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "got_revision_cp": "refs/heads/master@{#643731}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "parent_got_revision_cp": "refs/heads/master@{#643731}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "24025d13a3d457e28cdbe59dc91e73222da3af1f", "swarm_hashes": {"accessibility_unittests": "e64b88bcbe1179f6d81f7362bec9d96500d520be", "angle_unittests": "8fa699180f64cc4627ea447ae53881dfd5a034af", "app_list_unittests": "02dfd89c154f0ae7a82ea0b7b68c4b0be571ef73", "app_shell_unittests": "73777bed4cba13bb28f4a7d238edab673566b75d", "ash_unittests": "71c06c977f3ddecdb74fd12661d242474288a023", "aura_unittests": "1b9e5dc39de4c717df48498790cdf12b15fb781b", "base_unittests": "9ba9ecb6397bc5bed5b74500b6f24971bdcff0d5", "blink_common_unittests": "823cae7dfe14609028b63870c4b96b24a0fdde88", "blink_fuzzer_unittests": "712e5000a70c39da2e906e66c66b1167aa65e653", "blink_heap_unittests": "d10d2e28509448b149e46e26a0238d9b70dcc555", "blink_platform_unittests": "9ad52b8e8746b870817252b592d55b5d36438ce5", "blink_unittests": "d9c80f0734c0dfc55f5692d012432cd36a78a423", "boringssl_crypto_tests": "f6fdd625df20aec1de05caea9eaff99624324db7", "boringssl_ssl_tests": "812ad09c691f6e5e77f0c609a7fde5ab83766887", "browser_tests": "609023ce3961c8df58a7c4ef7acde88153923785", "cacheinvalidation_unittests": "f5b8c2a16c5703e95b45e1611e972a42e4745c49", "capture_unittests": "e9f97f6ca3f90e7bf7b4bd07341b09db08c92f7d", "cast_unittests": "30d02dc5332b66aee36944938c9d8051b3a67aea", "cc_unittests": "5fd296bf750f9477cfee6a2d2ede98f789b1d84e", "chrome_app_unittests": "dfd553a30ceb86cd08ac4d11fd022ce26307f01a", "chromedriver_unittests": "54e2974eaa37cd52a213cc87cac9cd540ed43302", "chromeos_components_unittests": "750480a2563dd293370eebefc400d06280c8daac", "chromeos_unittests": "446839e3944954709f088e0de729f5fd18432f57", "components_browsertests": "666ee63506e175358d3faa5dea6aabb4e0a5e43a", "components_unittests": "139ab46c3afd42cd3c2e4c1e82b587ae84142c2e", "compositor_unittests": "0817c123a43f8f1099aae83ef34d90f873a56325", "content_browsertests": "ee7334ebb986f5f0cd857916aab0e4f7de0ee729", "content_unittests": "6aafc4ea763dfb1381c02f12cddb600e0cde0643", "crypto_unittests": "bda07e809950bad650f7bb959fd6e32fd06837ea", "dbus_unittests": "e0e6adbf24f46347b2eea8daae7257f215d9f307", "device_unittests": "c4794958338778463ccc0f69d19031c1593f8b9f", "display_unittests": "707228d56b71f0d77c0cbf192a01fafd97cadc4c", "events_unittests": "253bdab2bde8e77e14a74094f9225ff71d10417f", "exo_unittests": "74c47884c09aca11a207d4e376178ded43ae820e", "extensions_browsertests": "63dcd7c85eee8b2dcbcbb8d8028ab41a68927000", "extensions_unittests": "c6306fab457ffb23d7293663911a66f7afed0d6a", "filesystem_service_unittests": "29b1744b158e73e980a83e61a0049fba28cdce4d", "gcm_unit_tests": "bc0ce5e5f1d992f7db7c820eedc3d00d915e0937", "gfx_unittests": "e094f212a05ad9cb7ac2dc23f09d1fdffd0e6092", "gl_unittests_ozone": "c49b99e7d6c70746d1e09024933e112eb32adb35", "google_apis_unittests": "76bbdbbe5e3fd4ef5b8be4d2548a53c3c4054c8f", "gpu_unittests": "1229541f3884f792fdb08d179da79ad491355111", "interactive_ui_tests": "5cee9610508ce8f7992acb9f95a8751825fb60f3", "ipc_tests": "6c2011b2aefd70eea3dc896b535b3783cc29645e", "jingle_unittests": "50068a1a2c508cbcb908d44fb3b67c0ea56c5c85", "keyboard_unittests": "b7ea2e90dd1d1a9b77d3264c6fbd5576e65a692f", "latency_unittests": "0748e6338a4de70a5fc1fdbf4c45945b1608b545", "leveldb_service_unittests": "97879d672b0babd91397319a70b94998d9c94c18", "libjingle_xmpp_unittests": "45db1df7828a48e33cc02882dca6525f59220997", "media_blink_unittests": "aec5bd53c36ef67ae7918abf9d566e9d0247d4e7", "media_service_unittests": "dd1e477f5d78f22e5797973893d05df67cebd27a", "media_unittests": "3bc32a8830e7cbf60dbbae637705a878b5e67469", "message_center_unittests": "35e6c4683f17977e9276d49d630e963ea23eb0c2", "midi_unittests": "6171f1bd07632ac259259dcd2eb7606f7036733a", "mojo_core_unittests": "e56c8c4a3154c072c5cc8b2985973b66450a9a75", "mojo_unittests": "1d5e40b04cffe375e15bf7c2dcd20d1ef9d759cc", "nacl_helper_nonsfi_unittests": "c84ff16e368053268ff6f5a34881019c9e45d02b", "nacl_loader_unittests": "c3243886c503904b3bacf60cf76f1bf60b7186d9", "native_theme_unittests": "86a7643e5ff1e180b8a34dab91c73d128237261f", "net_unittests": "82baf73a24b292aa1b0cce9c9307e9eabbba18f2", "ozone_gl_unittests": "94872d0292c59a8cee50b4fab5ba084964eba34c", "ozone_unittests": "cc2e56782215e8a62da2078d0fd6c4841224e531", "ozone_x11_unittests": "d3b60c43ddf4c3c396c64eef166fa2c2d22bf991", "pdf_unittests": "4fdb74d082859f50d720cf576182dc50c2f8195b", "perfetto_unittests": "5d8c491c19c3ad4b1daeccf129f71a2bd76296ee", "ppapi_unittests": "11a2e33db41121e102fe6ef1fa8bc3ed0ae1c062", "printing_unittests": "1fe4efcf41a9000303704a209d861e8d743e9b71", "remoting_unittests": "d665c9b8faced5300a7533cffaa6429d9d4d4123", "sandbox_linux_unittests": "e4d1ad8374c33b847b8b152c3dcc9ca6460b9258", "service_manager_unittests": "48a9529c8e12243154f1157cabcced59e245212d", "services_unittests": "a0bfb13fe742a512c91308b5fe5aca42693af384", "shell_dialogs_unittests": "eab64e7bacea6e74780ab6c02a29d0e8c395c603", "skia_unittests": "2c8b235d87bd7fdac84b5a08afc867685b6417ff", "snapshot_unittests": "44a4a0e75988af52a03f63bf09d67fd66f597bf7", "sql_unittests": "4229bc5954144b61acac98a41d4a68090715f108", "storage_unittests": "a75e190f5d9531963eac4603f9d548e9b62e8814", "sync_integration_tests": "82adff571f088b812b692726564d052c72780763", "traffic_annotation_auditor_unittests": "26e49645f979d46bffb1150017e0e0918d59ce49", "ui_base_unittests": "eedbaea22c4ced7255de07eb534378f13fd82169", "ui_chromeos_unittests": "db62467aa3a708637ad388f6d8bc2c4c7f579949", "ui_touch_selection_unittests": "1fa57521330981c93a8e50bf535e366c45a5f9c5", "unit_tests": "bc4483b81e5fe3cbe2bc3afcdbcbf3cc125c7fa4", "url_unittests": "63bf0ac3962e57d89e9ee9d002342e06ac55ba66", "usage_time_limit_unittests": "815ea1bd8d3d8bc0a0b09368c7a9a278f2014dce", "views_unittests": "a29ec6cd2a1af6b5ab4679e90c9cf4977d7bb80d", "viz_unittests": "3b1558a6e2ea9927303f270d53f20fdab15833f9", "wayland_client_perftests": "255db5d049e103f0474ea814131278a3aa30c8b6", "wm_unittests": "d0b438227fba5194322231fd77e153acad8bbfa4", "wtf_unittests": "ba23313940818e93b11b06fa2a3ab7624c6391cd"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpcseQNW.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp0m9HoQ', '-o', '/b/swarming/w/ir/tmp/t/tmpjLnm_H.json', '/b/swarming/w/ir/tmp/t/tmp0m9HoQ/43c9ee43dc0b8a10/output.json'] returned exit code 0