Back to build
Raw log | Switch to full mode | Login

python -u /b/s/w/ir/kitchen-checkout/build/scripts/tools/runit.py --show-path --with-third-party-lib -- python /b/s/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py --verbose -o /b/s/w/ir/tmp/t/tmp334yeq.json --task-output-dir /b/s/w/ir/tmp/t/tmpTJDAZD --merge-script /b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --merge-script-stdout-file /b/s/w/ir/tmp/t/tmpdplr_Jmerge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "vm258-m9", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1556259839643580, "id": "8915136998344281456", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Mac ASan 64 Tests (1)/52291", "builder:Mac ASan 64 Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2b08a071a2fa53807bdaf7ed61bb249d6294691c", "gitiles_ref:refs/heads/master", "parent_buildername:Mac ASan 64 Builder", "parent_buildnumber:81869", "scheduler_invocation_id:9080567060607902928", "scheduler_job_id:chromium/Mac ASan 64 Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Mac ASan 64 Tests (1)", "buildnumber": 52291, "got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "got_revision_cp": "refs/heads/master@{#654352}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "got_webrtc_revision_cp": "refs/heads/master@{#27778}", "mastername": "chromium.memory", "parent_buildername": "Mac ASan 64 Builder", "parent_got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "parent_got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "parent_got_revision_cp": "refs/heads/master@{#654352}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "parent_got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "parent_got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27778}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "swarm_hashes": {"accessibility_unittests": "db778aa035494ea06c64a6e20bbddfbce729fae4", "angle_unittests": "5928cf6eafeb37a47c5f167b8f10c1e34a5d33a9", "app_shell_unittests": "9e46482d3df5020b5843ba69e9a440d08984cbbb", "base_unittests": "10c70501fb003f98251eaa1e11b8aa7da6838773", "blink_common_unittests": "20e5eec4fc1e1803de30b709a219331bd04eb50e", "blink_fuzzer_unittests": "4704974ef2e2575a7de85d49342aa4669cba34b6", "blink_heap_unittests": "a739731193effe75d71e5cb0995fd979f0fbf61a", "blink_platform_unittests": "e8670f472fe8378fb88ace998794db5b9ae6bd0a", "blink_unittests": "fbc870a3b382fe8a45e62af5fc5287aed3e3ef02", "boringssl_crypto_tests": "94d5afdc2c9765339d6982156bec451848e01a40", "boringssl_ssl_tests": "3ef551a5b13e1bd8c2e2de6274e663902b3d0094", "browser_tests": "a9c155120af735723d3012c8c27ef1252cdf9a51", "cacheinvalidation_unittests": "a5ca45f76a7a883b7b5626f71ac94c45c5bebb3f", "capture_unittests": "29560bb2d114a94c24f9570d34c02a4e65b13801", "cast_unittests": "eaa867d783338c7e660e8c4d1e08e527330d01f3", "cc_unittests": "7055d49610cd31088f1d770d2709c7535bac08b0", "chrome_app_unittests": "8418b08d81271deaa4726bcbb5c890a43c5db990", "chromedriver_unittests": "c29536ea65c0f7444a9b74ee2540c50b24e8a386", "components_browsertests": "8ffa6377cacbedd3e8393ede31032df93a4e7d25", "components_unittests": "741bd3be26e122754d169e3bdd9fda014bb4f828", "content_browsertests": "b47cb719a2688ba4d09067bd571a65ef148c81f7", "content_unittests": "83e1b3ae932011426b3e41eebf8232aa1ef15747", "crashpad_tests": "9f5aa5272a521531e9e293434b1f7394636a5a04", "cronet_tests": "811a46c494b386c23547d3ba1b92d2a31215356d", "cronet_unittests": "2d873e63b1337131669d62c871bd85883be46a3d", "crypto_unittests": "d9d70e480a7172f69c2248858bb5c0dc5dcaa7d3", "device_unittests": "858b25dcc589c3b28cdc9deb5ec744116c3d175c", "display_unittests": "a9d4b9f5076d8a6507b833337d0a7aea302ba1db", "events_unittests": "5b7afb83616b3286c5fced88101b7065d5330e47", "extensions_browsertests": "2f95f8f43bcde508a935dda8bae68722de345e51", "extensions_unittests": "e30b59436b74b4857fd5e235fa2fc044ffb17c44", "filesystem_service_unittests": "5e1021099b4a7b8a0eaa9f1846767aecbfab07a0", "gcm_unit_tests": "2e8de3ec399e66ceb787b446ed550df07cfe0720", "gfx_unittests": "70c1a85ef3b0d1e658abe2332a9ca5f0dab442ed", "gin_unittests": "e76ca3101ec9a8ef3774918cc8c160283c1284be", "google_apis_unittests": "8f891803161ebdfd2057b731099283d0f894dc3f", "gpu_unittests": "acc1543f37cc8ba208280c4954f11d6d3a288c95", "headless_browsertests": "2422dfc4c30d1ac4e5f0f71c5339e2ab8f252dfd", "headless_unittests": "409e3db57a9d649108c1860ca6331c0937a5a08d", "interactive_ui_tests": "08a50e4590dd1f881e37f483a4e983fc50600238", "ipc_tests": "18d3186520e212f09d636fb78f7c93d0aae18b69", "jingle_unittests": "e1fc54e615f36b542780d0df4f4b416b948a94fd", "latency_unittests": "ed9a65aaf0d2a6b2fdd2b34d5260f7e908726413", "leveldb_service_unittests": "48ae89a4c0f2a2c68fab7078e9ae5db7f16fbdc1", "libjingle_xmpp_unittests": "dc95cffca67c946940ab835fd90d9f53479ba39c", "media_blink_unittests": "70baa9f66e605c064c29dc6a0916dce72ebb8ca9", "media_service_unittests": "c197cca6393a1c55d8030e291a4474284a2c8b0f", "media_unittests": "31625830ddafe86b50bd1ead646017c659d832b9", "message_center_unittests": "0477d462fcecf815d5b4f3b45ee14db48de8d928", "midi_unittests": "2df3ec5ef9d25f2669941c8a514de48a24627a4a", "mojo_unittests": "3e7e7ad90524693cb1ab4fdbc524c0fb799ab50b", "native_theme_unittests": "f689ea9cbcf20e4980e94433a2ef6954023b082a", "net_unittests": "618821cc684e95e942ff41526f4f2aaf6687cb91", "pdf_unittests": "785913c06cc5f0a56c7a3fb8eb053db51f339ebb", "perfetto_unittests": "f34fc79ab0f078cc2fdbfb5857bb50d3a864d678", "ppapi_unittests": "569165ffc9fe48839de8e89e05a5c2d7c8894ee5", "printing_unittests": "b9da9d66be5db2e055b44a7048af3e0b2db0c92f", "remoting_unittests": "0b3b5c49b475973ec840d502bb4d02de934ce212", "sandbox_mac_unittests": "842cf4ea5ce167fb98a442400ff10fcf9c1c3322", "service_manager_unittests": "98a20d71af4f7ad0599922c7d632d159bc90ef9f", "services_unittests": "1363629efea1d771d62e778948641564ca7a547a", "shell_dialogs_unittests": "9c60b80a4830422db2f88f9b6e68e1251bb1734d", "skia_unittests": "bf1b92076429317c40eb285e9bc9a188d7995235", "snapshot_unittests": "aebd826d417b24e581067480d3d701c6173aedea", "sql_unittests": "2529c7688048d3da0e6c707944bae4b132e722cd", "storage_unittests": "671b6b16953553f98b212fbf79aa5f9bdfc8f723", "sync_integration_tests": "f05a7e4a0bebc43689530bd74cd19e6a248f0f77", "ui_base_unittests": "438b9adaa05ea6ae97514b48adfd540ab05c2cae", "ui_touch_selection_unittests": "33bcea04d9174b9ee389491e1aa16d9ef187471d", "unit_tests": "69d0cc368ef7e489847ec88e62ee94b45c2d465e", "url_unittests": "0b3741f8ba205939421a02b5357290737c913e56", "views_unittests": "a8dee709d4ce7fe28319063cc2ff1d5078239829", "viz_unittests": "a4834f29cb7f908503f020f78a19ee5444a18fc1", "wtf_unittests": "7f50437f17922dc3e11ac1051083497743d45b8d"}}' --summary-json-file /b/s/w/ir/tmp/t/tmpuSVz_T.json -- swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/s/w/ir/tmp/t/tmpkY2iBa.json in dir /b/s/w/ir/k: allow_subannotations: True cmd: ['python', '-u', '/b/s/w/ir/kitchen-checkout/build/scripts/tools/runit.py', '--show-path', '--with-third-party-lib', '--', 'python', '/b/s/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py', '--verbose', '-o', '/b/s/w/ir/tmp/t/tmp334yeq.json', '--task-output-dir', '/b/s/w/ir/tmp/t/tmpTJDAZD', '--merge-script', '/b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/s/w/ir/tmp/t/tmpdplr_Jmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "vm258-m9", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1556259839643580, "id": "8915136998344281456", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Mac ASan 64 Tests (1)/52291", "builder:Mac ASan 64 Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2b08a071a2fa53807bdaf7ed61bb249d6294691c", "gitiles_ref:refs/heads/master", "parent_buildername:Mac ASan 64 Builder", "parent_buildnumber:81869", "scheduler_invocation_id:9080567060607902928", "scheduler_job_id:chromium/Mac ASan 64 Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Mac ASan 64 Tests (1)", "buildnumber": 52291, "got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "got_revision_cp": "refs/heads/master@{#654352}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "got_webrtc_revision_cp": "refs/heads/master@{#27778}", "mastername": "chromium.memory", "parent_buildername": "Mac ASan 64 Builder", "parent_got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "parent_got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "parent_got_revision_cp": "refs/heads/master@{#654352}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "parent_got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "parent_got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27778}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "swarm_hashes": {"accessibility_unittests": "db778aa035494ea06c64a6e20bbddfbce729fae4", "angle_unittests": "5928cf6eafeb37a47c5f167b8f10c1e34a5d33a9", "app_shell_unittests": "9e46482d3df5020b5843ba69e9a440d08984cbbb", "base_unittests": "10c70501fb003f98251eaa1e11b8aa7da6838773", "blink_common_unittests": "20e5eec4fc1e1803de30b709a219331bd04eb50e", "blink_fuzzer_unittests": "4704974ef2e2575a7de85d49342aa4669cba34b6", "blink_heap_unittests": "a739731193effe75d71e5cb0995fd979f0fbf61a", "blink_platform_unittests": "e8670f472fe8378fb88ace998794db5b9ae6bd0a", "blink_unittests": "fbc870a3b382fe8a45e62af5fc5287aed3e3ef02", "boringssl_crypto_tests": "94d5afdc2c9765339d6982156bec451848e01a40", "boringssl_ssl_tests": "3ef551a5b13e1bd8c2e2de6274e663902b3d0094", "browser_tests": "a9c155120af735723d3012c8c27ef1252cdf9a51", "cacheinvalidation_unittests": "a5ca45f76a7a883b7b5626f71ac94c45c5bebb3f", "capture_unittests": "29560bb2d114a94c24f9570d34c02a4e65b13801", "cast_unittests": "eaa867d783338c7e660e8c4d1e08e527330d01f3", "cc_unittests": "7055d49610cd31088f1d770d2709c7535bac08b0", "chrome_app_unittests": "8418b08d81271deaa4726bcbb5c890a43c5db990", "chromedriver_unittests": "c29536ea65c0f7444a9b74ee2540c50b24e8a386", "components_browsertests": "8ffa6377cacbedd3e8393ede31032df93a4e7d25", "components_unittests": "741bd3be26e122754d169e3bdd9fda014bb4f828", "content_browsertests": "b47cb719a2688ba4d09067bd571a65ef148c81f7", "content_unittests": "83e1b3ae932011426b3e41eebf8232aa1ef15747", "crashpad_tests": "9f5aa5272a521531e9e293434b1f7394636a5a04", "cronet_tests": "811a46c494b386c23547d3ba1b92d2a31215356d", "cronet_unittests": "2d873e63b1337131669d62c871bd85883be46a3d", "crypto_unittests": "d9d70e480a7172f69c2248858bb5c0dc5dcaa7d3", "device_unittests": "858b25dcc589c3b28cdc9deb5ec744116c3d175c", "display_unittests": "a9d4b9f5076d8a6507b833337d0a7aea302ba1db", "events_unittests": "5b7afb83616b3286c5fced88101b7065d5330e47", "extensions_browsertests": "2f95f8f43bcde508a935dda8bae68722de345e51", "extensions_unittests": "e30b59436b74b4857fd5e235fa2fc044ffb17c44", "filesystem_service_unittests": "5e1021099b4a7b8a0eaa9f1846767aecbfab07a0", "gcm_unit_tests": "2e8de3ec399e66ceb787b446ed550df07cfe0720", "gfx_unittests": "70c1a85ef3b0d1e658abe2332a9ca5f0dab442ed", "gin_unittests": "e76ca3101ec9a8ef3774918cc8c160283c1284be", "google_apis_unittests": "8f891803161ebdfd2057b731099283d0f894dc3f", "gpu_unittests": "acc1543f37cc8ba208280c4954f11d6d3a288c95", "headless_browsertests": "2422dfc4c30d1ac4e5f0f71c5339e2ab8f252dfd", "headless_unittests": "409e3db57a9d649108c1860ca6331c0937a5a08d", "interactive_ui_tests": "08a50e4590dd1f881e37f483a4e983fc50600238", "ipc_tests": "18d3186520e212f09d636fb78f7c93d0aae18b69", "jingle_unittests": "e1fc54e615f36b542780d0df4f4b416b948a94fd", "latency_unittests": "ed9a65aaf0d2a6b2fdd2b34d5260f7e908726413", "leveldb_service_unittests": "48ae89a4c0f2a2c68fab7078e9ae5db7f16fbdc1", "libjingle_xmpp_unittests": "dc95cffca67c946940ab835fd90d9f53479ba39c", "media_blink_unittests": "70baa9f66e605c064c29dc6a0916dce72ebb8ca9", "media_service_unittests": "c197cca6393a1c55d8030e291a4474284a2c8b0f", "media_unittests": "31625830ddafe86b50bd1ead646017c659d832b9", "message_center_unittests": "0477d462fcecf815d5b4f3b45ee14db48de8d928", "midi_unittests": "2df3ec5ef9d25f2669941c8a514de48a24627a4a", "mojo_unittests": "3e7e7ad90524693cb1ab4fdbc524c0fb799ab50b", "native_theme_unittests": "f689ea9cbcf20e4980e94433a2ef6954023b082a", "net_unittests": "618821cc684e95e942ff41526f4f2aaf6687cb91", "pdf_unittests": "785913c06cc5f0a56c7a3fb8eb053db51f339ebb", "perfetto_unittests": "f34fc79ab0f078cc2fdbfb5857bb50d3a864d678", "ppapi_unittests": "569165ffc9fe48839de8e89e05a5c2d7c8894ee5", "printing_unittests": "b9da9d66be5db2e055b44a7048af3e0b2db0c92f", "remoting_unittests": "0b3b5c49b475973ec840d502bb4d02de934ce212", "sandbox_mac_unittests": "842cf4ea5ce167fb98a442400ff10fcf9c1c3322", "service_manager_unittests": "98a20d71af4f7ad0599922c7d632d159bc90ef9f", "services_unittests": "1363629efea1d771d62e778948641564ca7a547a", "shell_dialogs_unittests": "9c60b80a4830422db2f88f9b6e68e1251bb1734d", "skia_unittests": "bf1b92076429317c40eb285e9bc9a188d7995235", "snapshot_unittests": "aebd826d417b24e581067480d3d701c6173aedea", "sql_unittests": "2529c7688048d3da0e6c707944bae4b132e722cd", "storage_unittests": "671b6b16953553f98b212fbf79aa5f9bdfc8f723", "sync_integration_tests": "f05a7e4a0bebc43689530bd74cd19e6a248f0f77", "ui_base_unittests": "438b9adaa05ea6ae97514b48adfd540ab05c2cae", "ui_touch_selection_unittests": "33bcea04d9174b9ee389491e1aa16d9ef187471d", "unit_tests": "69d0cc368ef7e489847ec88e62ee94b45c2d465e", "url_unittests": "0b3741f8ba205939421a02b5357290737c913e56", "views_unittests": "a8dee709d4ce7fe28319063cc2ff1d5078239829", "viz_unittests": "a4834f29cb7f908503f020f78a19ee5444a18fc1", "wtf_unittests": "7f50437f17922dc3e11ac1051083497743d45b8d"}}', '--summary-json-file', '/b/s/w/ir/tmp/t/tmpuSVz_T.json', '--', 'swarming', 'collect', '-server', 'https://chromium-swarm.appspot.com', '-worker', '50', '-task-summary-python', '-task-output-stdout', 'all', '-verbose', '-requests-json', '/b/s/w/ir/tmp/t/tmpkY2iBa.json'] env: FrozenDict([('FORCE_MAC_TOOLCHAIN', '1'), ('CHROME_HEADLESS', '1')]) env_prefixes: {'mapping': FrozenDict([('PATH', ('/b/s/w/ir/cache/swarming_client',))]), 'pathsep': ':'} env_suffixes: {'mapping': FrozenDict([]), 'pathsep': ':'} infra_step: False name_tokens: ['cacheinvalidation_unittests'] ok_ret: ALL_OK step_test_data: gen_default_step_test_data(...) trigger_specs: [] full environment: Apple_PubSub_Socket_Render: /private/tmp/com.apple.launchd.nh4JAOq66R/Render BOTO_CONFIG: /b/s/w/ir/tmp/gsutil-task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/s/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 49191 DOCKER_CONFIG: /b/s/w/ir/tmp/docker-cfg-task DOCKER_TMPDIR: /b/s/w/ir/tmp/docker-tmp-task FORCE_MAC_TOOLCHAIN: 1 GIT_CONFIG_NOSYSTEM: 1 GIT_TERMINAL_PROMPT: 0 HOME: /Users/chrome-bot INFRA_GIT_WRAPPER_HOME: /b/s/w/ir/tmp/git-home-task LOGDOG_COORDINATOR_HOST: logs.chromium.org LOGDOG_STREAM_PREFIX: buildbucket/cr-buildbucket.appspot.com/8915136998344281456 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/s/w/ir/tmp/ld.sock LOGNAME: chrome-bot LUCI_CONTEXT: /b/s/w/ir/tmp/luci_context.289183973 MAC_CHROMIUM_TMPDIR: /b/s/w/ir/tmp/t NO_GCE_CHECK: False PATH: /b/s/w/ir/cache/swarming_client:/b/s/w/ir/cipd_bin_packages:/b/s/w/ir/cipd_bin_packages/bin:/b/s/cipd_cache/bin:/opt/local/bin:/opt/local/sbin:/usr/local/sbin:/usr/local/git/bin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin PWD: /b/s/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 SHELL: /bin/bash SHLVL: 1 SSH_AUTH_SOCK: /private/tmp/com.apple.launchd.DmqxmYe2gU/Listeners SWARMING_BOT_ID: vm258-m9 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 4471222c02a0c211 TEMP: /b/s/w/ir/tmp/t TEMPDIR: /b/s/w/ir/tmp/t TMP: /b/s/w/ir/tmp/t TMPDIR: /b/s/w/ir/tmp/t USER: chrome-bot VERSIONER_PYTHON_PREFER_32_BIT: no VERSIONER_PYTHON_VERSION: 2.7 VPYTHON_VIRTUALENV_ROOT: /b/s/w/ir/cache/vpython XPC_FLAGS: 0x0 XPC_SERVICE_NAME: 0 _: /b/s/w/ir/cipd_bin_packages/vpython __CF_USER_TEXT_ENCODING: 0x1F4:0x0:0x0 Set PYTHONPATH: /b/s/w/ir/kitchen-checkout/build/scripts:/b/s/w/ir/kitchen-checkout/build/site_config:/b/s/w/ir/kitchen-checkout/build/third_party:/b/s/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/s/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/s/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/s/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/s/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/s/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/s/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/s/w/ir/kitchen-checkout/build/third_party/jinja2:/b/s/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/s/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/s/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/s/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/s/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/s/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/s/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/s/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/s/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/s/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/s/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/s/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/s/w/ir/kitchen-checkout/build/third_party/site-packages 2019-04-25 23:29:22,552 - root: [DEBUG] Using task_output_dir: '/b/s/w/ir/tmp/t/tmpTJDAZD' 2019-04-25 23:29:22,552 - root: [WARNING] task_output_dir '/b/s/w/ir/tmp/t/tmpTJDAZD' already exists! 2019-04-25 23:29:22,552 - root: [WARNING] task_output_dir existing content: [] 2019-04-25 23:29:22,553 - 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/s/w/ir/tmp/t/tmpkY2iBa.json -output-dir /b/s/w/ir/tmp/t/tmpTJDAZD -task-summary-json /b/s/w/ir/tmp/t/tmpuSVz_T.json [D2019-04-25T23:29:22.572890-07:00 8518 0 auth.go:1265] Minting a new token {"key":"luci_ctx/5350ca14132feb11e7e1b2cb1b6ea3e9e3e7c931b2ed8b6b1c19ae15698f39c2", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-25T23:29:22.573002-07:00 8518 0 luci_ctx.go:138] POST http://127.0.0.1:49179/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/5350ca14132feb11e7e1b2cb1b6ea3e9e3e7c931b2ed8b6b1c19ae15698f39c2", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-25T23:29:22.574992-07:00 8518 0 auth.go:1222] Token expires in 50m51.425053s {"key":"luci_ctx/5350ca14132feb11e7e1b2cb1b6ea3e9e3e7c931b2ed8b6b1c19ae15698f39c2", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 44712594aa0cea10: exit 0 Additional test environment: ASAN_OPTIONS=symbolize=0 handle_abort=1 CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 DYLD_LIBRARY_PATH=/b/s/w/ir/out/Release 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/ior7TFfM/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 [21327:775:0425/193017.170014:6800262216552:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006910 with delay 0 [21327:775:0425/193017.170807:6800262358924:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006910 [21327:775:0425/193017.171096:6800262647936: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 } [21327:775:0425/193017.171215:6800262774881:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24744 with a delay 500000, Now = 210919424 [21327:775:0425/193017.171291:6800262844020:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006930 with delay 500 [21327:775:0425/193017.171392:6800262943724:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006930 [21327:775:0425/193017.171577:6800263128196:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [21327:775:0425/193017.171649:6800263200423:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (3 ms) [1/28] ProtocolHandlerTest.TokenMissing (3 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [21327:775:0425/193017.172422:6800263973823:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006eb0 with delay 0 [21327:775:0425/193017.172501:6800264051905:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006eb0 [21327:775:0425/193017.172599:6800264150926:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 29736 with a delay 500000, Now = 210919424 [21327:775:0425/193017.172688:6800264239344:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006ed0 with delay 500 [21327:775:0425/193017.172771:6800264322566:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006ed0 [21327:775:0425/193017.172991:6800264542172:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [21327:775:0425/193017.173138:6800264695708: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 } [21327:775:0425/193017.173270:6800264821557: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 } } [21327:775:0425/193017.173521:6800265073122: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 } } } [21327:775:0425/193017.173721:6800265272440: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 [21327:775:0425/193017.174360:6800265919627:INFO:protocol-handler.cc(139)] Incoming message: { } [21327:775:0425/193017.174455:6800266006843:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [21327:775:0425/193017.174514:6800266064508:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [ RUN ] RecurringTaskTest.PeriodicTask [21327:775:0425/193017.174944:6800266495600:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -398038072 with a delay 10000, Now = 0 [21327:775:0425/193017.175005:6800266556368:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000007590 with delay 10 [21327:775:0425/193017.175079:6800266630210:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000007590 [21327:775:0425/193017.175134:6800266685306:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [21327:775:0425/193017.175196:6800266746680:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038072 with a delay 60000, Now = 10000 [21327:775:0425/193017.175251:6800266801896:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x6020000075b0 with delay 60 [21327:775:0425/193017.175320:6800266870651:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x6020000075b0 [21327:775:0425/193017.175373:6800266924108:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [21327:775:0425/193017.175420:6800266970458:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038072 with a delay 60000, Now = 70000 [21327:775:0425/193017.175466:6800267016911:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000075d0 with delay 60 [21327:775:0425/193017.175513:6800267063370:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000075d0 [21327:775:0425/193017.175590:6800267141505:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [21327:775:0425/193017.175637:6800267187511:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038072 with a delay 60000, Now = 130000 [21327:775:0425/193017.175692:6800267243411:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000075f0 with delay 60 [21327:775:0425/193017.175738:6800267288991:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000075f0 [21327:775:0425/193017.175781:6800267332123:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [21327:775:0425/193017.175825:6800267376056:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038072 with a delay 60000, Now = 190000 [21327:775:0425/193017.175871:6800267421684:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x602000007610 with delay 60 [21327:775:0425/193017.175917:6800267467330:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x602000007610 [21327:775:0425/193017.175959:6800267509605:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [21327:775:0425/193017.176013:6800267563625:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038072 with a delay 60000, Now = 250000 [21327:775:0425/193017.176059:6800267615104:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000007630 with delay 60 [21327:775:0425/193017.176126:6800267676964:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000007630 [21327:775:0425/193017.176180:6800267731165:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [21327:775:0425/193017.176224:6800267774936:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038072 with a delay 60000, Now = 310000 [21327:775:0425/193017.176270:6800267820820:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000007650 with delay 60 [21327:775:0425/193017.176315:6800267866160:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000007650 [21327:775:0425/193017.176371:6800267921996:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [21327:775:0425/193017.176416:6800267966801:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038072 with a delay 60000, Now = 370000 [21327:775:0425/193017.176461:6800268012250:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000007670 with delay 60 [21327:775:0425/193017.176507:6800268058241:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000007670 [21327:775:0425/193017.176568:6800268119221:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (2 ms) [4/28] RecurringTaskTest.PeriodicTask (2 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [21327:775:0425/193017.176988:6800268539886:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -398038424 with a delay 10000, Now = 0 [21327:775:0425/193017.177061:6800268611840:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x6020000076f0 with delay 10 [21327:775:0425/193017.177149:6800268714492:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x6020000076f0 [21327:775:0425/193017.177230:6800268789705:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [21327:775:0425/193017.177310:6800268861405:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038424 with a delay 50000, Now = 10000 [21327:775:0425/193017.177366:6800268917824:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000007710 with delay 50 [21327:775:0425/193017.177436:6800268987181:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000007710 [21327:775:0425/193017.177490:6800269048923:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [21327:775:0425/193017.177556:6800269107498:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038424 with a delay 149000, Now = 60000 [21327:775:0425/193017.177620:6800269171797:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000007730 with delay 149 [21327:775:0425/193017.177678:6800269229488:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000007730 [21327:775:0425/193017.177736:6800269287408:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [21327:775:0425/193017.177804:6800269354631:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038424 with a delay 248000, Now = 210000 [21327:775:0425/193017.177866:6800269417367:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000007750 with delay 248 [21327:775:0425/193017.177932:6800269483483:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000007750 [21327:775:0425/193017.177978:6800269537218:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [21327:775:0425/193017.178060:6800269611368:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038424 with a delay 446000, Now = 460000 [21327:775:0425/193017.178127:6800269678130:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000007770 with delay 446 [21327:775:0425/193017.178192:6800269743445:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000007770 [21327:775:0425/193017.178260:6800269811066:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [21327:775:0425/193017.178321:6800269871817:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038424 with a delay 842000, Now = 910000 [21327:775:0425/193017.178376:6800269927112:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000007790 with delay 842 [21327:775:0425/193017.178447:6800269998218:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000007790 [21327:775:0425/193017.178521:6800270072600:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [21327:775:0425/193017.178567:6800270117770:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038424 with a delay 1040000, Now = 1760000 [21327:775:0425/193017.178613:6800270164685:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x6020000077b0 with delay 1040 [21327:775:0425/193017.178664:6800270214862:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x6020000077b0 [21327:775:0425/193017.178707:6800270258285:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [21327:775:0425/193017.178763:6800270314423:INFO:recurring-task.cc(55)] [Retry] Scheduling -398038424 with a delay 1040000, Now = 2800000 [21327:775:0425/193017.178811:6800270362030:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x6020000077d0 with delay 1040 [21327:775:0425/193017.178861:6800270412163:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x6020000077d0 [21327:775:0425/193017.178904:6800270455310:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (3 ms) [ RUN ] RecurringTaskTest.OneShotTask [21327:775:0425/193017.179249:6800270809351:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -398038392 with a delay 10000, Now = 0 [21327:775:0425/193017.179323:6800270874948:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000007850 with delay 10 [21327:775:0425/193017.179380:6800270930825:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000007850 [21327:775:0425/193017.179449:6800271000027:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [21327:775:0425/193017.179524:6800271075196:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -398038392 with a delay 10000, Now = 10000 [21327:775:0425/193017.179596:6800271147151:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000007870 with delay 10 [21327:775:0425/193017.179668:6800271219932:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000007870 [21327:775:0425/193017.179721:6800271272008:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (0 ms) [6/28] RecurringTaskTest.OneShotTask (0 ms) [ RUN ] ThrottleTest.ThrottlingScripted [21327:775:0425/193017.180219:6800271770886:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x6020000078f0 with delay 920 [21327:775:0425/193017.180291:6800271842378:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x6020000078f0 [21327:775:0425/193017.180410:6800271961277:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000007910 with delay 45000 [21327:775:0425/193017.180685:6800272236085:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000007910 [ OK ] ThrottleTest.ThrottlingScripted (0 ms) [7/28] ThrottleTest.ThrottlingScripted (0 ms) [ RUN ] ThrottleTest.ThrottlingStorm [21327:775:0425/193017.180888:6800272440337:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000007990 with delay 990 [21327:775:0425/193017.180966:6800272517366:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000007990 [21327:775:0425/193017.181031:6800272581903:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x6020000079b0 with delay 1000 [21327:775:0425/193017.181085:6800272636076:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x6020000079b0 [21327:775:0425/193017.181133:6800272683828:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x6020000079d0 with delay 1000 [21327:775:0425/193017.181186:6800272736598:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x6020000079d0 [21327:775:0425/193017.181233:6800272784263:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x6020000079f0 with delay 1000 [21327:775:0425/193017.181286:6800272836477:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x6020000079f0 [21327:775:0425/193017.181361:6800272943517:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000007a10 with delay 1000 [21327:775:0425/193017.181450:6800273001705:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000007a10 [21327:775:0425/193017.181500:6800273050841:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000007a30 with delay 1000 [21327:775:0425/193017.181552:6800273103131:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000007a30 [21327:775:0425/193017.181613:6800273164801:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000007a50 with delay 54000 [21327:775:0425/193017.182095:6800273646504:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000007a50 [21327:775:0425/193017.182155:6800273706617:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000007a70 with delay 1000 [21327:775:0425/193017.182210:6800273761508:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000007a70 [21327:775:0425/193017.182283:6800273834312:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000007a90 with delay 1000 [21327:775:0425/193017.182338:6800273889388:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000007a90 [21327:775:0425/193017.182387:6800273937958:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000007ab0 with delay 1000 [21327:775:0425/193017.182439:6800273990365:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000007ab0 [21327:775:0425/193017.182487:6800274038397:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000007ad0 with delay 1000 [21327:775:0425/193017.182540:6800274096458:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000007ad0 [21327:775:0425/193017.182596:6800274147544:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000007af0 with delay 1000 [21327:775:0425/193017.182650:6800274201022:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000007af0 [21327:775:0425/193017.182718:6800274269651:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000007b10 with delay 1000 [21327:775:0425/193017.182773:6800274323966:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000007b10 [21327:775:0425/193017.182820:6800274371050:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000007b30 with delay 54000 [21327:775:0425/193017.183280:6800274830871:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000007b30 [21327:775:0425/193017.183328:6800274878783:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000007b50 with delay 1000 [21327:775:0425/193017.183381:6800274932251:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000007b50 [21327:775:0425/193017.183430:6800274981427:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000007b70 with delay 1000 [21327:775:0425/193017.183483:6800275034064:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000007b70 [21327:775:0425/193017.183541:6800275117211:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000007b90 with delay 1000 [21327:775:0425/193017.183653:6800275205572:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000007b90 [21327:775:0425/193017.183709:6800275260005:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000007bb0 with delay 1000 [21327:775:0425/193017.183771:6800275322266:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000007bb0 [21327:775:0425/193017.183823:6800275374040:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000007bd0 with delay 1000 [21327:775:0425/193017.183877:6800275428580:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000007bd0 [21327:775:0425/193017.183926:6800275477646:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000007bf0 with delay 1000 [21327:775:0425/193017.183979:6800275530485:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000007bf0 [21327:775:0425/193017.184036:6800275586847:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000007c10 with delay 54000 [21327:775:0425/193017.184495:6800276046545:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000007c10 [21327:775:0425/193017.184544:6800276094926:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000007c30 with delay 1000 [21327:775:0425/193017.184596:6800276147282:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000007c30 [21327:775:0425/193017.184687:6800276238165:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000007c50 with delay 1000 [21327:775:0425/193017.184742:6800276293038:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000007c50 [21327:775:0425/193017.184799:6800276350030:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000007c70 with delay 1000 [21327:775:0425/193017.184853:6800276403850:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000007c70 [21327:775:0425/193017.184912:6800276463378:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000007c90 with delay 1000 [21327:775:0425/193017.184966:6800276516664:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000007c90 [21327:775:0425/193017.185014:6800276565084:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000007cb0 with delay 1000 [21327:775:0425/193017.185073:6800276624356:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000007cb0 [21327:775:0425/193017.185122:6800276673617:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x602000007cd0 with delay 1000 [21327:775:0425/193017.185175:6800276726156:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x602000007cd0 [21327:775:0425/193017.185229:6800276780791:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x602000007cf0 with delay 54000 [21327:775:0425/193017.185700:6800277251143:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x602000007cf0 [21327:775:0425/193017.185759:6800277310541:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x602000007d10 with delay 1000 [21327:775:0425/193017.185813:6800277364096:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x602000007d10 [21327:775:0425/193017.185861:6800277411942:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000007d30 with delay 1000 [21327:775:0425/193017.185913:6800277463721:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000007d30 [21327:775:0425/193017.185960:6800277511300:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000007d50 with delay 1000 [21327:775:0425/193017.186013:6800277564561:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000007d50 [21327:775:0425/193017.186061:6800277612038:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000007d70 with delay 1000 [21327:775:0425/193017.186113:6800277664087:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000007d70 [21327:775:0425/193017.186171:6800277722217:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000007d90 with delay 1000 [21327:775:0425/193017.186224:6800277775670:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000007d90 [21327:775:0425/193017.186272:6800277823302:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000007db0 with delay 1000 [21327:775:0425/193017.186325:6800277875921:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000007db0 [21327:775:0425/193017.186372:6800277922871:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x602000007dd0 with delay 54000 [21327:775:0425/193017.186853:6800278404618:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x602000007dd0 [ OK ] ThrottleTest.ThrottlingStorm (6 ms) [8/28] ThrottleTest.ThrottlingStorm (6 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [21326:775:0425/193017.160696:6800252737791:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006910 with delay 0 [21326:775:0425/193017.161832:6800253391885:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006910 [21326:775:0425/193017.162070:6800253621026: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 } [21326:775:0425/193017.162214:6800253775500:INFO:recurring-task.cc(55)] [Startup] Scheduling 24744 with a delay 500000, Now = 210919424 [21326:775:0425/193017.162312:6800253863022:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006ab0 with delay 500 [21326:775:0425/193017.162396:6800253953948:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006ab0 [21326:775:0425/193017.162850:6800254408463: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 (5 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (5 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [21326:775:0425/193017.164931:6800256483011: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 [21326:775:0425/193017.165761:6800257327900:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000076f0 with delay 0 [21326:775:0425/193017.165956:6800257525744:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007710 with delay 0 [21326:775:0425/193017.166106:6800257678744:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007730 with delay 0 [21326:775:0425/193017.166269:6800257820862:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007750 with delay 0 [21326:775:0425/193017.166340:6800257890487:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007770 with delay 0 [21326:775:0425/193017.166421:6800257971808:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007790 with delay 0 [21326:775:0425/193017.167060:6800258611712:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000076f0 [21326:775:0425/193017.167248:6800258801780: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 } [21326:775:0425/193017.167384:6800258942024:INFO:recurring-task.cc(55)] [Send-info] Scheduling 69032 with a delay 500000, Now = 210919424 [21326:775:0425/193017.167485:6800259036901:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007930 with delay 500 [21326:775:0425/193017.167558:6800259109503:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007710 [21326:775:0425/193017.167644:6800259194562:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007730 [21326:775:0425/193017.167697:6800259247263:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007750 [21326:775:0425/193017.167769:6800259319896:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007770 [21326:775:0425/193017.167820:6800259370168:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007790 [21326:775:0425/193017.167911:6800259461906:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [21326:775:0425/193017.167984:6800259535191:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007930 [21326:775:0425/193017.168280:6800259831761:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [21326:775:0425/193017.169103:6800260662352: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 (5 ms) [11/28] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [21326:775:0425/193017.171345:6800262902937: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 [21326:775:0425/193017.172170:6800263722867: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 } } [21326:775:0425/193017.172309:6800263861091: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" } [21326:775:0425/193017.172433:6800263983851: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 } } [21326:775:0425/193017.172586:6800264144608: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 [21326:775:0425/193017.173227:6800264778691: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 } } [21326:775:0425/193017.173373:6800264924765: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 [21326:775:0425/193017.174137:6800265694783: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 [21326:775:0425/193017.174888:6800266439816: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" } } [21326:775:0425/193017.174985:6800266536483:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009470 with delay 0 [21326:775:0425/193017.175038:6800266589017:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009470 [21326:775:0425/193017.175156:6800266707788: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 } [21326:775:0425/193017.175242:6800266794191:INFO:recurring-task.cc(55)] [Send-info] Scheduling 100136 with a delay 500000, Now = 210919424 [21326:775:0425/193017.175309:6800266860847:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009490 with delay 500 [21326:775:0425/193017.175369:6800266920400:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009490 [21326:775:0425/193017.175435:6800266985980:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (11 ms) [16/28] ProtocolHandlerTest.ConfigMessage (11 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [21326:775:0425/193017.185686:6800277239396: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 [21326:775:0425/193017.186505:6800278057798: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 (0 ms) [18/28] ProtocolHandlerTest.TokenMismatch (0 ms) [ RUN ] InvalidationClientImplTest.Start [21325:775:0425/193017.166773:6800258793694:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006c50 with delay 0 [21325:775:0425/193017.167551:6800259110046:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.168111:6800259662380:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007170 with delay 0 [21325:775:0425/193017.168183:6800259740795:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006c50 [21325:775:0425/193017.168251:6800259802147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007170 [21325:775:0425/193017.168376:6800259933426:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.168550:6800260101082:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007230 with delay 0 [21325:775:0425/193017.168629:6800260179258:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007230 [21325:775:0425/193017.168683:6800260234112:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.168752:6800260302607:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007270 with delay 0 [21325:775:0425/193017.168822:6800260371931:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007270 [21325:775:0425/193017.168881:6800260431897:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.168977:6800260535236:INFO:recurring-task.cc(55)] [Startup] Scheduling 25000 with a delay 0, Now = 210919424 [21325:775:0425/193017.169053:6800260611078:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0 [21325:775:0425/193017.169128:6800260678231:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290 [21325:775:0425/193017.169256:6800260813733:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3141367351861484821" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.169357:6800260907953:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 25256 with a delay 500000, Now = 210919424 [21325:775:0425/193017.169441:6800260991453:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000072b0 with delay 500 [21325:775:0425/193017.169523:6800261073692:INFO:recurring-task.cc(55)] [Retry] Scheduling 25000 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.169599:6800261149471:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000072d0 with delay 60000 [21325:775:0425/193017.169655:6800261205990:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000072b0 [21325:775:0425/193017.169720:6800261270617:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.169861:6800261412016:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.170132:6800261684040: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: "3141367351861484821" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.170457:6800262015201:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007370 with delay 0 [21325:775:0425/193017.170557:6800262108962:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007370 [21325:775:0425/193017.170781:6800262332702:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3141367351861484821" 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" } } [21325:775:0425/193017.170951:6800262501838:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3141367351861484821" [21325:775:0425/193017.171020:6800262570570:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.171076:6800262635131:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 21720 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.171158:6800262709311:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007390 with delay 1200000 [21325:775:0425/193017.171227:6800262778255:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.171517:6800263074634:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.171608:6800263159662:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 21384 with a delay 0, Now = 211419424 [21325:775:0425/193017.171672:6800263222928:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000075b0 with delay 0 [21325:775:0425/193017.171799:6800263350155: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 [21325:775:0425/193017.171887:6800263437853:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000075b0 [21325:775:0425/193017.172041:6800263598978:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007670 with delay 0 [21325:775:0425/193017.172127:6800263678292:INFO:recurring-task.cc(55)] [Retry] Scheduling 21384 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.172188:6800263739728:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076b0 with delay 10000 [21325:775:0425/193017.172244:6800263794811:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007670 [21325:775:0425/193017.172298:6800263848154:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (7 ms) [19/28] InvalidationClientImplTest.Start (7 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [21325:775:0425/193017.173250:6800264801574:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007f10 with delay 0 [21325:775:0425/193017.173317:6800264867911: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 [21325:775:0425/193017.173935:6800265486570:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0 [21325:775:0425/193017.174001:6800265551997:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.174450:6800266001742:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008e10 with delay 0 [21325:775:0425/193017.174532:6800266083688:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0 [21325:775:0425/193017.174582:6800266132652:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008e10 [21325:775:0425/193017.174665:6800266216455:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.174759:6800266309853:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008ed0 with delay 0 [21325:775:0425/193017.174820:6800266370847:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008ed0 [21325:775:0425/193017.174865:6800266415952:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.174940:6800266490773:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f10 with delay 0 [21325:775:0425/193017.174997:6800266547635:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008f10 [21325:775:0425/193017.175050:6800266600350:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.175107:6800266665962:INFO:recurring-task.cc(55)] [Startup] Scheduling 81704 with a delay 0, Now = 210919424 [21325:775:0425/193017.175177:6800266755887:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f30 with delay 0 [21325:775:0425/193017.175269:6800266819800:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008f30 [21325:775:0425/193017.175364:6800266915011:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4322720334023358916" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.175436:6800266987007:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 81960 with a delay 500000, Now = 210919424 [21325:775:0425/193017.175504:6800267055375:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f50 with delay 500 [21325:775:0425/193017.175573:6800267124948:INFO:recurring-task.cc(55)] [Retry] Scheduling 81704 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.175650:6800267201268:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f70 with delay 60000 [21325:775:0425/193017.175727:6800267278751:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008f50 [21325:775:0425/193017.175781:6800267332150:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.175863:6800267413722:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.176032:6800267583354: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: "-4322720334023358916" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.176184:6800267735311:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009010 with delay 0 [21325:775:0425/193017.176247:6800267798372:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009010 [21325:775:0425/193017.176439:6800267990035:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4322720334023358916" 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" } } [21325:775:0425/193017.176542:6800268100740:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4322720334023358916" [21325:775:0425/193017.176619:6800268177961:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.176696:6800268247431:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 89656 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.176753:6800268303640:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009030 with delay 1200000 [21325:775:0425/193017.176808:6800268358880:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.177003:6800268561114:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.177115:6800268666807:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 66120 with a delay 0, Now = 211419424 [21325:775:0425/193017.177174:6800268724996:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009250 with delay 0 [21325:775:0425/193017.177273:6800268824410: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 [21325:775:0425/193017.177335:6800268886348:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009250 [21325:775:0425/193017.177426:6800268977780:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009310 with delay 0 [21325:775:0425/193017.177495:6800269045711:INFO:recurring-task.cc(55)] [Retry] Scheduling 66120 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.177562:6800269112711:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009350 with delay 10000 [21325:775:0425/193017.177618:6800269168478:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009310 [21325:775:0425/193017.177668:6800269219535:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.177825:6800269376332:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009370 with delay 0 [21325:775:0425/193017.177880:6800269431448:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000009370 [21325:775:0425/193017.177966:6800269517502:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [21325:775:0425/193017.178028:6800269579093:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [21325:775:0425/193017.178080:6800269630953:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [21325:775:0425/193017.178200:6800269751270:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 81960 with a delay 500000, Now = 211469424 [21325:775:0425/193017.178264:6800269815592:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009390 with delay 500 [21325:775:0425/193017.178341:6800269892517:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 81832 with a delay 60000000, Now = 211469424 [21325:775:0425/193017.178398:6800269948902:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000093b0 with delay 60000 [21325:775:0425/193017.178479:6800270029898:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009390 [21325:775:0425/193017.178539:6800270095947:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.178622:6800270173462:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.178685:6800270235950:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [21325:775:0425/193017.178880:6800270431552: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 } } } [21325:775:0425/193017.179037:6800270588335:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.179211:6800270762015:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000009450 with delay 0 [21325:775:0425/193017.179270:6800270831618:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009450 [21325:775:0425/193017.179515:6800271067136: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 } } } } [21325:775:0425/193017.179701:6800271252702: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 [21325:775:0425/193017.179830:6800271381642:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [21325:775:0425/193017.179952:6800271503212:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [21325:775:0425/193017.180058:6800271609687:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [21325:775:0425/193017.180205:6800271756212:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000009350 [ OK ] InvalidationClientImplTest.Register (7 ms) [21/28] InvalidationClientImplTest.Register (7 ms) [ RUN ] InvalidationClientImplTest.Invalidations [21325:775:0425/193017.181118:6800272670354:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a030 with delay 0 [21325:775:0425/193017.181185:6800272736296:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.181641:6800273192927:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a710 with delay 0 [21325:775:0425/193017.181700:6800273251802:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a030 [21325:775:0425/193017.181763:6800273313768:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a710 [21325:775:0425/193017.181840:6800273391220:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.181928:6800273487735:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a7d0 with delay 0 [21325:775:0425/193017.182003:6800273554413:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a7d0 [21325:775:0425/193017.182049:6800273600034:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.182128:6800273679971:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a810 with delay 0 [21325:775:0425/193017.182178:6800273729172:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a810 [21325:775:0425/193017.182223:6800273773860:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.182306:6800273858313:INFO:recurring-task.cc(55)] [Startup] Scheduling 112808 with a delay 0, Now = 210919424 [21325:775:0425/193017.182373:6800273924918:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a830 with delay 0 [21325:775:0425/193017.182460:6800274011275:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a830 [21325:775:0425/193017.182547:6800274098582:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2327626716099392592" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.182632:6800274184022:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 113064 with a delay 500000, Now = 210919424 [21325:775:0425/193017.182697:6800274255095:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a850 with delay 500 [21325:775:0425/193017.182758:6800274316577:INFO:recurring-task.cc(55)] [Retry] Scheduling 112808 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.182819:6800274369926:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a870 with delay 60000 [21325:775:0425/193017.182869:6800274420281:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a850 [21325:775:0425/193017.182924:6800274474792:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.182991:6800274541975:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.183149:6800274700600: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: "-2327626716099392592" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.183295:6800274846766:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a910 with delay 0 [21325:775:0425/193017.183370:6800274920990:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a910 [21325:775:0425/193017.183512:6800275063314:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2327626716099392592" 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" } } [21325:775:0425/193017.183622:6800275174400:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2327626716099392592" [21325:775:0425/193017.183681:6800275233478:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.183754:6800275305875:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 94760 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.183809:6800275360493:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a930 with delay 1200000 [21325:775:0425/193017.183867:6800275418367:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.184029:6800275581632:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.184128:6800275683760:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 72456 with a delay 0, Now = 211419424 [21325:775:0425/193017.184195:6800275746572:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ab50 with delay 0 [21325:775:0425/193017.184281:6800275832794: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 [21325:775:0425/193017.184366:6800275917793:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ab50 [21325:775:0425/193017.184458:6800276009794:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ac10 with delay 0 [21325:775:0425/193017.184521:6800276072492:INFO:recurring-task.cc(55)] [Retry] Scheduling 72456 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.184590:6800276141862:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ac50 with delay 10000 [21325:775:0425/193017.184639:6800276190402:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ac10 [21325:775:0425/193017.184684:6800276234590:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.184761:6800276312246:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.184855:6800276406614:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000ac70 with delay 0 [21325:775:0425/193017.184905:6800276464546:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000ac70 [21325:775:0425/193017.185174:6800276726353: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 } } } [21325:775:0425/193017.185297:6800276848451: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 [21325:775:0425/193017.185397:6800276949067: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" } [21325:775:0425/193017.185544:6800277096078:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [21325:775:0425/193017.185654:6800277205534:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [21325:775:0425/193017.185766:6800277317631:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b050 with delay 0 [21325:775:0425/193017.185827:6800277378250:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b070 with delay 0 [21325:775:0425/193017.185898:6800277449595:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b090 with delay 0 [21325:775:0425/193017.185959:6800277510662:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x60200000b050 [21325:775:0425/193017.186042:6800277593450:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 113064 with a delay 500000, Now = 211519424 [21325:775:0425/193017.186120:6800277671967:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b0b0 with delay 500 [21325:775:0425/193017.186180:6800277730691:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x60200000b070 [21325:775:0425/193017.186251:6800277802086:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x60200000b090 [21325:775:0425/193017.186317:6800277869435:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x60200000b0b0 [21325:775:0425/193017.186367:6800277917917:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.186450:6800278001030:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.186497:6800278062227:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [21325:775:0425/193017.186739:6800278291312: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 (7 ms) [22/28] InvalidationClientImplTest.Invalidations (7 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [21325:775:0425/193017.187705:6800279258495:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b990 with delay 0 [21325:775:0425/193017.187829:6800279383118:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.188151:6800279705121:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000beb0 with delay 0 [21325:775:0425/193017.188212:6800279764314:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b990 [21325:775:0425/193017.188293:6800279844961:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000beb0 [21325:775:0425/193017.188382:6800279934116:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.188528:6800280082707:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bf70 with delay 0 [21325:775:0425/193017.188599:6800280150613:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000bf70 [21325:775:0425/193017.188647:6800280198981:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.188722:6800280274412:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bfb0 with delay 0 [21325:775:0425/193017.188782:6800280333593:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000bfb0 [21325:775:0425/193017.188829:6800280380415:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.188900:6800280452675:INFO:recurring-task.cc(55)] [Startup] Scheduling 142504 with a delay 0, Now = 210919424 [21325:775:0425/193017.188951:6800280510771:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bfd0 with delay 0 [21325:775:0425/193017.189016:6800280567177:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000bfd0 [21325:775:0425/193017.189114:6800280667051:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8797369627917628121" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.189210:6800280762411:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 142760 with a delay 500000, Now = 210919424 [21325:775:0425/193017.189322:6800280875057:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bff0 with delay 500 [21325:775:0425/193017.189385:6800280937131:INFO:recurring-task.cc(55)] [Retry] Scheduling 142504 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.189458:6800281009813:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c010 with delay 60000 [21325:775:0425/193017.189517:6800281068128:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000bff0 [21325:775:0425/193017.189598:6800281149333:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.189663:6800281214302:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.189804:6800281356414: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: "8797369627917628121" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.189960:6800281512730:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c0b0 with delay 0 [21325:775:0425/193017.190022:6800281573368:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c0b0 [21325:775:0425/193017.190161:6800281712800:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8797369627917628121" 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" } } [21325:775:0425/193017.190236:6800281803958:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8797369627917628121" [21325:775:0425/193017.190320:6800281871491:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.190391:6800281942697:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 98808 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.190455:6800282006752:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c0d0 with delay 1200000 [21325:775:0425/193017.190506:6800282057767:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.190693:6800282251928:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.190761:6800282312714:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 78216 with a delay 0, Now = 211419424 [21325:775:0425/193017.190819:6800282370254:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c2f0 with delay 0 [21325:775:0425/193017.190889:6800282440537: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 [21325:775:0425/193017.190961:6800282512650:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c2f0 [21325:775:0425/193017.191061:6800282613138:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c3b0 with delay 0 [21325:775:0425/193017.191126:6800282677416:INFO:recurring-task.cc(55)] [Retry] Scheduling 78216 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.191196:6800282748234:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c3f0 with delay 10000 [21325:775:0425/193017.191246:6800282797960:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c3b0 [21325:775:0425/193017.191301:6800282852666:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.191414:6800282965970:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.191498:6800283049958:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000c410 with delay 0 [21325:775:0425/193017.191563:6800283115080:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000c410 [21325:775:0425/193017.191695:6800283247010: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 } } [21325:775:0425/193017.191845:6800283397558: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 [21325:775:0425/193017.191913:6800283465676:INFO:protocol-handler.cc(294)] Adding subtree: { } [21325:775:0425/193017.191971:6800283531216:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 142760 with a delay 500000, Now = 211469424 [21325:775:0425/193017.192037:6800283589237:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000c430 with delay 500 [21325:775:0425/193017.192103:6800283654240:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [21325:775:0425/193017.192346:6800283897714: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 } [21325:775:0425/193017.192439:6800283990701:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000c430 [21325:775:0425/193017.192495:6800284046940:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.192645:6800284197033:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.192702:6800284253828:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [21325:775:0425/193017.193007:6800284559735: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 } } [21325:775:0425/193017.193213:6800284765366:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000c3f0 [ OK ] InvalidationClientImplTest.ServerRequests (6 ms) [23/28] InvalidationClientImplTest.ServerRequests (6 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [21325:775:0425/193017.194111:6800285663535:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd10 with delay 0 [21325:775:0425/193017.194180:6800285731642:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.194486:6800286038050:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d2d0 with delay 0 [21325:775:0425/193017.194539:6800286090852:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cd10 [21325:775:0425/193017.194595:6800286146202:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d2d0 [21325:775:0425/193017.194667:6800286218790:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.194764:6800286315798:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d390 with delay 0 [21325:775:0425/193017.194834:6800286385681:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d390 [21325:775:0425/193017.194881:6800286433037:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.194930:6800286489513:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0 [21325:775:0425/193017.194987:6800286538442:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0 [21325:775:0425/193017.195032:6800286583095:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.195092:6800286643960:INFO:recurring-task.cc(55)] [Startup] Scheduling 169768 with a delay 0, Now = 210919424 [21325:775:0425/193017.195141:6800286693137:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3f0 with delay 0 [21325:775:0425/193017.195204:6800286756186:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3f0 [21325:775:0425/193017.195289:6800286841390:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "4546383816781663394" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.195352:6800286912647:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 170024 with a delay 500000, Now = 210919424 [21325:775:0425/193017.195418:6800286969653:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d410 with delay 500 [21325:775:0425/193017.195473:6800287025021:INFO:recurring-task.cc(55)] [Retry] Scheduling 169768 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.195534:6800287086280:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d430 with delay 60000 [21325:775:0425/193017.195585:6800287136718:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d410 [21325:775:0425/193017.195645:6800287197074:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.195715:6800287266957:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.195874:6800287426352: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: "4546383816781663394" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.196017:6800287568937:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d4d0 with delay 0 [21325:775:0425/193017.196085:6800287636722:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d4d0 [21325:775:0425/193017.196227:6800287779415:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "4546383816781663394" 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" } } [21325:775:0425/193017.196322:6800287875082:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "4546383816781663394" [21325:775:0425/193017.196381:6800287933376:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.196443:6800287995270:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 102328 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.196506:6800288058515:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d4f0 with delay 1200000 [21325:775:0425/193017.196565:6800288117680:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.196722:6800288274670:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.196790:6800288342607:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 83208 with a delay 0, Now = 211419424 [21325:775:0425/193017.196847:6800288398618:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d710 with delay 0 [21325:775:0425/193017.196922:6800288474340: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 [21325:775:0425/193017.197017:6800288569694:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d710 [21325:775:0425/193017.197150:6800288703668:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d7d0 with delay 0 [21325:775:0425/193017.197223:6800288774950:INFO:recurring-task.cc(55)] [Retry] Scheduling 83208 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.197273:6800288825496:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d810 with delay 10000 [21325:775:0425/193017.197331:6800288883031:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d7d0 [21325:775:0425/193017.197376:6800288927872:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.197442:6800289001440:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.197569:6800289121734:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000d830 with delay 0 [21325:775:0425/193017.197621:6800289172411:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000d830 [21325:775:0425/193017.197757:6800289309808: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" } } [21325:775:0425/193017.197884:6800289436816: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 [21325:775:0425/193017.197972:6800289524202:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [21325:775:0425/193017.198152:6800289704154:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000d810 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [21325:775:0425/193017.198935:6800290487768:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e190 with delay 0 [21325:775:0425/193017.199003:6800290555173:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.199330:6800290882413:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e810 with delay 0 [21325:775:0425/193017.199383:6800290935594:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e190 [21325:775:0425/193017.199462:6800291014100:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e810 [21325:775:0425/193017.199576:6800291128320:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.199677:6800291229097:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e8d0 with delay 0 [21325:775:0425/193017.199747:6800291299740:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e8d0 [21325:775:0425/193017.199795:6800291346998:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.199851:6800291403553:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e910 with delay 0 [21325:775:0425/193017.199901:6800291452417:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e910 [21325:775:0425/193017.199954:6800291506512:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.200017:6800291569730:INFO:recurring-task.cc(55)] [Startup] Scheduling 192424 with a delay 0, Now = 210919424 [21325:775:0425/193017.200067:6800291627578:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e930 with delay 0 [21325:775:0425/193017.200125:6800291677087:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e930 [21325:775:0425/193017.200208:6800291759880:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1320075299693261877" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.200274:6800291826632:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 192680 with a delay 500000, Now = 210919424 [21325:775:0425/193017.200325:6800291877073:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e950 with delay 500 [21325:775:0425/193017.200415:6800291967930:INFO:recurring-task.cc(55)] [Retry] Scheduling 192424 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.200472:6800292024718:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e970 with delay 60000 [21325:775:0425/193017.200524:6800292075366:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000e950 [21325:775:0425/193017.200586:6800292138351:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.200660:6800292212160:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.200818:6800292370456: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: "1320075299693261877" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.200947:6800292500077:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ea10 with delay 0 [21325:775:0425/193017.201007:6800292559601:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ea10 [21325:775:0425/193017.201133:6800292685126:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1320075299693261877" 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" } } [21325:775:0425/193017.201214:6800292773314:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1320075299693261877" [21325:775:0425/193017.201287:6800292839153:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.201352:6800292904656:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 105496 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.201408:6800292959900:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ea30 with delay 1200000 [21325:775:0425/193017.201473:6800293025133:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.201639:6800293198267:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.201706:6800293258851:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 86472 with a delay 0, Now = 211419424 [21325:775:0425/193017.201765:6800293317191:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ec50 with delay 0 [21325:775:0425/193017.201842:6800293394166: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 [21325:775:0425/193017.201911:6800293463486:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ec50 [21325:775:0425/193017.202002:6800293554913:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ed10 with delay 0 [21325:775:0425/193017.202066:6800293618638:INFO:recurring-task.cc(55)] [Retry] Scheduling 86472 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.202123:6800293675502:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ed50 with delay 10000 [21325:775:0425/193017.202180:6800293731600:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ed10 [21325:775:0425/193017.202224:6800293775907:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.202299:6800293851782:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000ed70 with delay 0 [21325:775:0425/193017.202348:6800293900097:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000ed70 [21325:775:0425/193017.202418:6800293969926:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [21325:775:0425/193017.202504:6800294056830:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 192680 with a delay 500000, Now = 211469424 [21325:775:0425/193017.202569:6800294121596:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000ed90 with delay 500 [21325:775:0425/193017.202638:6800294205686:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 192552 with a delay 60000000, Now = 211469424 [21325:775:0425/193017.202705:6800294257241:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000edb0 with delay 60000 [21325:775:0425/193017.202767:6800294319487:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000ed90 [21325:775:0425/193017.202822:6800294373993:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.202887:6800294439246:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.202949:6800294500948:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [21325:775:0425/193017.203117:6800294669478: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 } } } [21325:775:0425/193017.203230:6800294783237:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.203303:6800294855197:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000ee50 with delay 0 [21325:775:0425/193017.203367:6800294919546:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000ee50 [21325:775:0425/193017.203492:6800295045950: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" } } [21325:775:0425/193017.203599:6800295151851: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 [21325:775:0425/193017.203666:6800295218928:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [21325:775:0425/193017.203784:6800295336313:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [21325:775:0425/193017.203966:6800295518636:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000ed50 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [21325:775:0425/193017.204780:6800296333021:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f8b0 with delay 0 [21325:775:0425/193017.204859:6800296411708:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.205099:6800296652156:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fdd0 with delay 0 [21325:775:0425/193017.205159:6800296711320:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000f8b0 [21325:775:0425/193017.205207:6800296758906:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fdd0 [21325:775:0425/193017.205284:6800296836587:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.205367:6800296919595:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fe90 with delay 0 [21325:775:0425/193017.205436:6800296988688:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fe90 [21325:775:0425/193017.205506:6800297058511:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.205564:6800297116173:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fed0 with delay 0 [21325:775:0425/193017.205618:6800297170668:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fed0 [21325:775:0425/193017.205664:6800297216315:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.205730:6800297283393:INFO:recurring-task.cc(55)] [Startup] Scheduling 220840 with a delay 0, Now = 210919424 [21325:775:0425/193017.205788:6800297340681:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fef0 with delay 0 [21325:775:0425/193017.205843:6800297394995:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fef0 [21325:775:0425/193017.205938:6800297491470:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7875436727345435535" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.206003:6800297555791:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 221096 with a delay 500000, Now = 210919424 [21325:775:0425/193017.206060:6800297612377:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ff10 with delay 500 [21325:775:0425/193017.206114:6800297666791:INFO:recurring-task.cc(55)] [Retry] Scheduling 220840 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.206178:6800297730510:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ff30 with delay 60000 [21325:775:0425/193017.206237:6800297789636:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ff10 [21325:775:0425/193017.206293:6800297845598:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.206364:6800297916774:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.206518:6800298070438: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: "7875436727345435535" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.206668:6800298220866:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ffd0 with delay 0 [21325:775:0425/193017.206721:6800298273332:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ffd0 [21325:775:0425/193017.206846:6800298399233:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7875436727345435535" 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" } } [21325:775:0425/193017.206942:6800298494653:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7875436727345435535" [21325:775:0425/193017.207000:6800298552728:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.207060:6800298612313:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 108840 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.207118:6800298670731:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000fff0 with delay 1200000 [21325:775:0425/193017.207185:6800298737113:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.207408:6800298960777:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.207485:6800299037794:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 91464 with a delay 0, Now = 211419424 [21325:775:0425/193017.207549:6800299102148:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000010210 with delay 0 [21325:775:0425/193017.207638:6800299190786: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 [21325:775:0425/193017.207703:6800299256058:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000010210 [21325:775:0425/193017.207797:6800299350137:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000102d0 with delay 0 [21325:775:0425/193017.207868:6800299420067:INFO:recurring-task.cc(55)] [Retry] Scheduling 91464 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.207925:6800299477835:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000010310 with delay 10000 [21325:775:0425/193017.207987:6800299539320:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000102d0 [21325:775:0425/193017.208041:6800299594082:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.208119:6800299671361:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000010330 with delay 0 [21325:775:0425/193017.208202:6800299754534:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000010330 [21325:775:0425/193017.208266:6800299818446:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [21325:775:0425/193017.208363:6800299916167:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 221096 with a delay 500000, Now = 211469424 [21325:775:0425/193017.208416:6800299968321:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000010350 with delay 500 [21325:775:0425/193017.208479:6800300031815:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 220968 with a delay 60000000, Now = 211469424 [21325:775:0425/193017.208535:6800300087582:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000010370 with delay 60000 [21325:775:0425/193017.208598:6800300150560:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000010350 [21325:775:0425/193017.208647:6800300199130:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.208724:6800300277475:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.208774:6800300326816:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [21325:775:0425/193017.208907:6800300466146: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 } } } [21325:775:0425/193017.209071:6800300623536:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000010310 [21325:775:0425/193017.209356:6800300908153:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000ff30 [21325:775:0425/193017.209405:6800300956947:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x602000010370 [21325:775:0425/193017.209492:6800301044515: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 [21325:775:0425/193017.209562:6800301115080:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [21325:775:0425/193017.209665:6800301217914: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 } [21325:775:0425/193017.209729:6800301282067:INFO:recurring-task.cc(55)] [Send-info] Scheduling 221096 with a delay 500000, Now = 271469424 [21325:775:0425/193017.209785:6800301337861:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000010410 with delay 500 [21325:775:0425/193017.209835:6800301387127:INFO:recurring-task.cc(55)] [Retry] Scheduling 220968 with a delay 60000000, Now = 271469424 [21325:775:0425/193017.209891:6800301444026:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000010430 with delay 60000 [21325:775:0425/193017.209948:6800301500094:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x602000010410 [21325:775:0425/193017.209996:6800301548117:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.210072:6800301633107:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.210130:6800301682062:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [21325:775:0425/193017.210306:6800301858870:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 1 registration_digest: "\327\003\047\242\324@\3740-O\354\3229\352\000\231\340\204\224\323" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: "3" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } server_registration_summary_requested: true } } [ OK ] InvalidationClientImplTest.NetworkTimeouts (6 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (6 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [21325:775:0425/193017.211229:6800302782671:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010d10 with delay 0 [21325:775:0425/193017.211299:6800302852280:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.211551:6800303104540:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011230 with delay 0 [21325:775:0425/193017.211612:6800303164947:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000010d10 [21325:775:0425/193017.211660:6800303212728:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011230 [21325:775:0425/193017.211746:6800303299415:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.211832:6800303384997:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000112f0 with delay 0 [21325:775:0425/193017.211894:6800303446732:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000112f0 [21325:775:0425/193017.211941:6800303493141:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.211998:6800303550540:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011330 with delay 0 [21325:775:0425/193017.212055:6800303606790:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011330 [21325:775:0425/193017.212100:6800303651856:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.212165:6800303718435:INFO:recurring-task.cc(55)] [Startup] Scheduling 249768 with a delay 0, Now = 210919424 [21325:775:0425/193017.212231:6800303783902:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011350 with delay 0 [21325:775:0425/193017.212305:6800303858115:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011350 [21325:775:0425/193017.212389:6800303941960:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "9080613330989733563" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.212446:6800303999220:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 250024 with a delay 500000, Now = 210919424 [21325:775:0425/193017.212503:6800304055953:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011370 with delay 500 [21325:775:0425/193017.212564:6800304116998:INFO:recurring-task.cc(55)] [Retry] Scheduling 249768 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.212616:6800304168530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011390 with delay 60000 [21325:775:0425/193017.212675:6800304227601:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011370 [21325:775:0425/193017.212730:6800304289541:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.212801:6800304353977:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.212945:6800304498282: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: "9080613330989733563" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.213105:6800304657761:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011430 with delay 0 [21325:775:0425/193017.213195:6800304749020:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011430 [21325:775:0425/193017.213331:6800304884982:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "9080613330989733563" 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" } } [21325:775:0425/193017.213420:6800304972581:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "9080613330989733563" [21325:775:0425/193017.213477:6800305029691:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.213543:6800305106151:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 111480 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.213613:6800305166467:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011450 with delay 1200000 [21325:775:0425/193017.213673:6800305226016:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.213861:6800305413858:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.213932:6800305485071:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 97032 with a delay 0, Now = 211419424 [21325:775:0425/193017.213988:6800305542257:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011670 with delay 0 [21325:775:0425/193017.214068:6800305621090: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 [21325:775:0425/193017.214151:6800305703681:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011670 [21325:775:0425/193017.214238:6800305791547:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011730 with delay 0 [21325:775:0425/193017.214303:6800305855922:INFO:recurring-task.cc(55)] [Retry] Scheduling 97032 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.214361:6800305914371:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011770 with delay 10000 [21325:775:0425/193017.214423:6800305975536:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011730 [21325:775:0425/193017.214468:6800306020437:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.214535:6800306087792:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.214609:6800306161930:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000011790 with delay 0 [21325:775:0425/193017.214665:6800306217960:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000011790 [21325:775:0425/193017.214775:6800306328730: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" } } [21325:775:0425/193017.214899:6800306451613:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000011770 [21325:775:0425/193017.215233:6800306786373: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 (5 ms) [27/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [21325:775:0425/193017.215804:6800307357727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011ff0 with delay 0 [21325:775:0425/193017.215882:6800307434793:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [21325:775:0425/193017.216118:6800307670970:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012510 with delay 0 [21325:775:0425/193017.216170:6800307722966:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011ff0 [21325:775:0425/193017.216242:6800307794895:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012510 [21325:775:0425/193017.216312:6800307864753:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [21325:775:0425/193017.216396:6800307949642:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000125d0 with delay 0 [21325:775:0425/193017.216459:6800308011594:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000125d0 [21325:775:0425/193017.216506:6800308058280:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [21325:775:0425/193017.216568:6800308121547:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012610 with delay 0 [21325:775:0425/193017.216619:6800308171313:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012610 [21325:775:0425/193017.216664:6800308216295:INFO:invalidation-client-core.cc(351)] Starting with no previous state [21325:775:0425/193017.216726:6800308279017:INFO:recurring-task.cc(55)] [Startup] Scheduling 271400 with a delay 0, Now = 210919424 [21325:775:0425/193017.216775:6800308334754:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012630 with delay 0 [21325:775:0425/193017.216831:6800308383610:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012630 [21325:775:0425/193017.216928:6800308481615:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-10578501476245620" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [21325:775:0425/193017.216999:6800308552754:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 271656 with a delay 500000, Now = 210919424 [21325:775:0425/193017.217050:6800308602508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012650 with delay 500 [21325:775:0425/193017.217106:6800308658600:INFO:recurring-task.cc(55)] [Retry] Scheduling 271400 with a delay 60000000, Now = 210919424 [21325:775:0425/193017.217170:6800308722886:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012670 with delay 60000 [21325:775:0425/193017.217227:6800308779875:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012650 [21325:775:0425/193017.217282:6800308834326:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.217345:6800308897598:INFO:invalidation-client-core.cc(488)] Return client token = "" [21325:775:0425/193017.217495:6800309048453: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: "-10578501476245620" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [21325:775:0425/193017.217675:6800309229012:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012710 with delay 0 [21325:775:0425/193017.217734:6800309287166:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012710 [21325:775:0425/193017.217867:6800309420412:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-10578501476245620" 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" } } [21325:775:0425/193017.217970:6800309531997:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-10578501476245620" [21325:775:0425/193017.218032:6800309584888:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [21325:775:0425/193017.218106:6800309659897:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 113944 with a delay 1200000000, Now = 211419424 [21325:775:0425/193017.218164:6800309717691:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012730 with delay 1200000 [21325:775:0425/193017.218216:6800309768860:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [21325:775:0425/193017.218382:6800309949797:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.218456:6800310009066:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 100296 with a delay 0, Now = 211419424 [21325:775:0425/193017.218520:6800310072911:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012950 with delay 0 [21325:775:0425/193017.218589:6800310142361: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 [21325:775:0425/193017.218653:6800310205896:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012950 [21325:775:0425/193017.218745:6800310298380:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012a10 with delay 0 [21325:775:0425/193017.218844:6800310397702:INFO:recurring-task.cc(55)] [Retry] Scheduling 100296 with a delay 10000000, Now = 211419424 [21325:775:0425/193017.218902:6800310455433:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012a50 with delay 10000 [21325:775:0425/193017.218952:6800310504287:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012a10 [21325:775:0425/193017.218997:6800310549427:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [21325:775:0425/193017.219114:6800310667276:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000012a50 [21325:775:0425/193017.219389:6800310941600:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x602000012670 [21325:775:0425/193017.224621:6800316174393:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x602000012730 [21325:775:0425/193017.224700:6800316253462:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.224775:6800316328356:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [21325:775:0425/193017.224825:6800316378618:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [21325:775:0425/193017.225011:6800316565137: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 } [21325:775:0425/193017.225090:6800316644390:INFO:recurring-task.cc(55)] [Send-info] Scheduling 271656 with a delay 500000, Now = 1411419424 [21325:775:0425/193017.225165:6800316718777:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000012a70 with delay 500 [21325:775:0425/193017.225230:6800316783321:INFO:recurring-task.cc(55)] [Retry] Scheduling 113944 with a delay 1200000000, Now = 1411419424 [21325:775:0425/193017.225295:6800316848673:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000012a90 with delay 1200000 [21325:775:0425/193017.225353:6800316905670:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x602000012a70 [21325:775:0425/193017.225400:6800316953298:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.225488:6800317041267:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [21325:775:0425/193017.225543:6800317096376:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [21325:775:0425/193017.225751:6800317304702: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 (11 ms) [28/28] InvalidationClientImplTest.Heartbeats (11 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-04-25 23:29:23,377 - root: [DEBUG] Contents of task_output_dir: ['/b/s/w/ir/tmp/t/tmpTJDAZD/44712594aa0cea10'] 2019-04-25 23:29:23,377 - root: [DEBUG] Found shard_json_files: ['/b/s/w/ir/tmp/t/tmpTJDAZD/44712594aa0cea10/output.json'] 2019-04-25 23:29:23,377 - root: [INFO] merge_cmd: /b/s/w/ir/cache/vpython/5b0713/bin/python /b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"bot_id": "vm258-m9", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1556259839643580, "id": "8915136998344281456", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Mac ASan 64 Tests (1)/52291", "builder:Mac ASan 64 Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2b08a071a2fa53807bdaf7ed61bb249d6294691c", "gitiles_ref:refs/heads/master", "parent_buildername:Mac ASan 64 Builder", "parent_buildnumber:81869", "scheduler_invocation_id:9080567060607902928", "scheduler_job_id:chromium/Mac ASan 64 Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Mac ASan 64 Tests (1)", "buildnumber": 52291, "got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "got_revision_cp": "refs/heads/master@{#654352}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "got_webrtc_revision_cp": "refs/heads/master@{#27778}", "mastername": "chromium.memory", "parent_buildername": "Mac ASan 64 Builder", "parent_got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "parent_got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "parent_got_revision_cp": "refs/heads/master@{#654352}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "parent_got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "parent_got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27778}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "swarm_hashes": {"accessibility_unittests": "db778aa035494ea06c64a6e20bbddfbce729fae4", "angle_unittests": "5928cf6eafeb37a47c5f167b8f10c1e34a5d33a9", "app_shell_unittests": "9e46482d3df5020b5843ba69e9a440d08984cbbb", "base_unittests": "10c70501fb003f98251eaa1e11b8aa7da6838773", "blink_common_unittests": "20e5eec4fc1e1803de30b709a219331bd04eb50e", "blink_fuzzer_unittests": "4704974ef2e2575a7de85d49342aa4669cba34b6", "blink_heap_unittests": "a739731193effe75d71e5cb0995fd979f0fbf61a", "blink_platform_unittests": "e8670f472fe8378fb88ace998794db5b9ae6bd0a", "blink_unittests": "fbc870a3b382fe8a45e62af5fc5287aed3e3ef02", "boringssl_crypto_tests": "94d5afdc2c9765339d6982156bec451848e01a40", "boringssl_ssl_tests": "3ef551a5b13e1bd8c2e2de6274e663902b3d0094", "browser_tests": "a9c155120af735723d3012c8c27ef1252cdf9a51", "cacheinvalidation_unittests": "a5ca45f76a7a883b7b5626f71ac94c45c5bebb3f", "capture_unittests": "29560bb2d114a94c24f9570d34c02a4e65b13801", "cast_unittests": "eaa867d783338c7e660e8c4d1e08e527330d01f3", "cc_unittests": "7055d49610cd31088f1d770d2709c7535bac08b0", "chrome_app_unittests": "8418b08d81271deaa4726bcbb5c890a43c5db990", "chromedriver_unittests": "c29536ea65c0f7444a9b74ee2540c50b24e8a386", "components_browsertests": "8ffa6377cacbedd3e8393ede31032df93a4e7d25", "components_unittests": "741bd3be26e122754d169e3bdd9fda014bb4f828", "content_browsertests": "b47cb719a2688ba4d09067bd571a65ef148c81f7", "content_unittests": "83e1b3ae932011426b3e41eebf8232aa1ef15747", "crashpad_tests": "9f5aa5272a521531e9e293434b1f7394636a5a04", "cronet_tests": "811a46c494b386c23547d3ba1b92d2a31215356d", "cronet_unittests": "2d873e63b1337131669d62c871bd85883be46a3d", "crypto_unittests": "d9d70e480a7172f69c2248858bb5c0dc5dcaa7d3", "device_unittests": "858b25dcc589c3b28cdc9deb5ec744116c3d175c", "display_unittests": "a9d4b9f5076d8a6507b833337d0a7aea302ba1db", "events_unittests": "5b7afb83616b3286c5fced88101b7065d5330e47", "extensions_browsertests": "2f95f8f43bcde508a935dda8bae68722de345e51", "extensions_unittests": "e30b59436b74b4857fd5e235fa2fc044ffb17c44", "filesystem_service_unittests": "5e1021099b4a7b8a0eaa9f1846767aecbfab07a0", "gcm_unit_tests": "2e8de3ec399e66ceb787b446ed550df07cfe0720", "gfx_unittests": "70c1a85ef3b0d1e658abe2332a9ca5f0dab442ed", "gin_unittests": "e76ca3101ec9a8ef3774918cc8c160283c1284be", "google_apis_unittests": "8f891803161ebdfd2057b731099283d0f894dc3f", "gpu_unittests": "acc1543f37cc8ba208280c4954f11d6d3a288c95", "headless_browsertests": "2422dfc4c30d1ac4e5f0f71c5339e2ab8f252dfd", "headless_unittests": "409e3db57a9d649108c1860ca6331c0937a5a08d", "interactive_ui_tests": "08a50e4590dd1f881e37f483a4e983fc50600238", "ipc_tests": "18d3186520e212f09d636fb78f7c93d0aae18b69", "jingle_unittests": "e1fc54e615f36b542780d0df4f4b416b948a94fd", "latency_unittests": "ed9a65aaf0d2a6b2fdd2b34d5260f7e908726413", "leveldb_service_unittests": "48ae89a4c0f2a2c68fab7078e9ae5db7f16fbdc1", "libjingle_xmpp_unittests": "dc95cffca67c946940ab835fd90d9f53479ba39c", "media_blink_unittests": "70baa9f66e605c064c29dc6a0916dce72ebb8ca9", "media_service_unittests": "c197cca6393a1c55d8030e291a4474284a2c8b0f", "media_unittests": "31625830ddafe86b50bd1ead646017c659d832b9", "message_center_unittests": "0477d462fcecf815d5b4f3b45ee14db48de8d928", "midi_unittests": "2df3ec5ef9d25f2669941c8a514de48a24627a4a", "mojo_unittests": "3e7e7ad90524693cb1ab4fdbc524c0fb799ab50b", "native_theme_unittests": "f689ea9cbcf20e4980e94433a2ef6954023b082a", "net_unittests": "618821cc684e95e942ff41526f4f2aaf6687cb91", "pdf_unittests": "785913c06cc5f0a56c7a3fb8eb053db51f339ebb", "perfetto_unittests": "f34fc79ab0f078cc2fdbfb5857bb50d3a864d678", "ppapi_unittests": "569165ffc9fe48839de8e89e05a5c2d7c8894ee5", "printing_unittests": "b9da9d66be5db2e055b44a7048af3e0b2db0c92f", "remoting_unittests": "0b3b5c49b475973ec840d502bb4d02de934ce212", "sandbox_mac_unittests": "842cf4ea5ce167fb98a442400ff10fcf9c1c3322", "service_manager_unittests": "98a20d71af4f7ad0599922c7d632d159bc90ef9f", "services_unittests": "1363629efea1d771d62e778948641564ca7a547a", "shell_dialogs_unittests": "9c60b80a4830422db2f88f9b6e68e1251bb1734d", "skia_unittests": "bf1b92076429317c40eb285e9bc9a188d7995235", "snapshot_unittests": "aebd826d417b24e581067480d3d701c6173aedea", "sql_unittests": "2529c7688048d3da0e6c707944bae4b132e722cd", "storage_unittests": "671b6b16953553f98b212fbf79aa5f9bdfc8f723", "sync_integration_tests": "f05a7e4a0bebc43689530bd74cd19e6a248f0f77", "ui_base_unittests": "438b9adaa05ea6ae97514b48adfd540ab05c2cae", "ui_touch_selection_unittests": "33bcea04d9174b9ee389491e1aa16d9ef187471d", "unit_tests": "69d0cc368ef7e489847ec88e62ee94b45c2d465e", "url_unittests": "0b3741f8ba205939421a02b5357290737c913e56", "views_unittests": "a8dee709d4ce7fe28319063cc2ff1d5078239829", "viz_unittests": "a4834f29cb7f908503f020f78a19ee5444a18fc1", "wtf_unittests": "7f50437f17922dc3e11ac1051083497743d45b8d"}} --summary-json /b/s/w/ir/tmp/t/tmpuSVz_T.json --task-output-dir /b/s/w/ir/tmp/t/tmpTJDAZD -o /b/s/w/ir/tmp/t/tmp334yeq.json /b/s/w/ir/tmp/t/tmpTJDAZD/44712594aa0cea10/output.json Running ['/b/s/w/ir/cache/vpython/5b0713/bin/python', '/b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "vm258-m9", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1556259839643580, "id": "8915136998344281456", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Mac ASan 64 Tests (1)/52291", "builder:Mac ASan 64 Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2b08a071a2fa53807bdaf7ed61bb249d6294691c", "gitiles_ref:refs/heads/master", "parent_buildername:Mac ASan 64 Builder", "parent_buildnumber:81869", "scheduler_invocation_id:9080567060607902928", "scheduler_job_id:chromium/Mac ASan 64 Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Mac ASan 64 Tests (1)", "buildnumber": 52291, "got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "got_revision_cp": "refs/heads/master@{#654352}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "got_webrtc_revision_cp": "refs/heads/master@{#27778}", "mastername": "chromium.memory", "parent_buildername": "Mac ASan 64 Builder", "parent_got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "parent_got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "parent_got_revision_cp": "refs/heads/master@{#654352}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "parent_got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "parent_got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27778}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "swarm_hashes": {"accessibility_unittests": "db778aa035494ea06c64a6e20bbddfbce729fae4", "angle_unittests": "5928cf6eafeb37a47c5f167b8f10c1e34a5d33a9", "app_shell_unittests": "9e46482d3df5020b5843ba69e9a440d08984cbbb", "base_unittests": "10c70501fb003f98251eaa1e11b8aa7da6838773", "blink_common_unittests": "20e5eec4fc1e1803de30b709a219331bd04eb50e", "blink_fuzzer_unittests": "4704974ef2e2575a7de85d49342aa4669cba34b6", "blink_heap_unittests": "a739731193effe75d71e5cb0995fd979f0fbf61a", "blink_platform_unittests": "e8670f472fe8378fb88ace998794db5b9ae6bd0a", "blink_unittests": "fbc870a3b382fe8a45e62af5fc5287aed3e3ef02", "boringssl_crypto_tests": "94d5afdc2c9765339d6982156bec451848e01a40", "boringssl_ssl_tests": "3ef551a5b13e1bd8c2e2de6274e663902b3d0094", "browser_tests": "a9c155120af735723d3012c8c27ef1252cdf9a51", "cacheinvalidation_unittests": "a5ca45f76a7a883b7b5626f71ac94c45c5bebb3f", "capture_unittests": "29560bb2d114a94c24f9570d34c02a4e65b13801", "cast_unittests": "eaa867d783338c7e660e8c4d1e08e527330d01f3", "cc_unittests": "7055d49610cd31088f1d770d2709c7535bac08b0", "chrome_app_unittests": "8418b08d81271deaa4726bcbb5c890a43c5db990", "chromedriver_unittests": "c29536ea65c0f7444a9b74ee2540c50b24e8a386", "components_browsertests": "8ffa6377cacbedd3e8393ede31032df93a4e7d25", "components_unittests": "741bd3be26e122754d169e3bdd9fda014bb4f828", "content_browsertests": "b47cb719a2688ba4d09067bd571a65ef148c81f7", "content_unittests": "83e1b3ae932011426b3e41eebf8232aa1ef15747", "crashpad_tests": "9f5aa5272a521531e9e293434b1f7394636a5a04", "cronet_tests": "811a46c494b386c23547d3ba1b92d2a31215356d", "cronet_unittests": "2d873e63b1337131669d62c871bd85883be46a3d", "crypto_unittests": "d9d70e480a7172f69c2248858bb5c0dc5dcaa7d3", "device_unittests": "858b25dcc589c3b28cdc9deb5ec744116c3d175c", "display_unittests": "a9d4b9f5076d8a6507b833337d0a7aea302ba1db", "events_unittests": "5b7afb83616b3286c5fced88101b7065d5330e47", "extensions_browsertests": "2f95f8f43bcde508a935dda8bae68722de345e51", "extensions_unittests": "e30b59436b74b4857fd5e235fa2fc044ffb17c44", "filesystem_service_unittests": "5e1021099b4a7b8a0eaa9f1846767aecbfab07a0", "gcm_unit_tests": "2e8de3ec399e66ceb787b446ed550df07cfe0720", "gfx_unittests": "70c1a85ef3b0d1e658abe2332a9ca5f0dab442ed", "gin_unittests": "e76ca3101ec9a8ef3774918cc8c160283c1284be", "google_apis_unittests": "8f891803161ebdfd2057b731099283d0f894dc3f", "gpu_unittests": "acc1543f37cc8ba208280c4954f11d6d3a288c95", "headless_browsertests": "2422dfc4c30d1ac4e5f0f71c5339e2ab8f252dfd", "headless_unittests": "409e3db57a9d649108c1860ca6331c0937a5a08d", "interactive_ui_tests": "08a50e4590dd1f881e37f483a4e983fc50600238", "ipc_tests": "18d3186520e212f09d636fb78f7c93d0aae18b69", "jingle_unittests": "e1fc54e615f36b542780d0df4f4b416b948a94fd", "latency_unittests": "ed9a65aaf0d2a6b2fdd2b34d5260f7e908726413", "leveldb_service_unittests": "48ae89a4c0f2a2c68fab7078e9ae5db7f16fbdc1", "libjingle_xmpp_unittests": "dc95cffca67c946940ab835fd90d9f53479ba39c", "media_blink_unittests": "70baa9f66e605c064c29dc6a0916dce72ebb8ca9", "media_service_unittests": "c197cca6393a1c55d8030e291a4474284a2c8b0f", "media_unittests": "31625830ddafe86b50bd1ead646017c659d832b9", "message_center_unittests": "0477d462fcecf815d5b4f3b45ee14db48de8d928", "midi_unittests": "2df3ec5ef9d25f2669941c8a514de48a24627a4a", "mojo_unittests": "3e7e7ad90524693cb1ab4fdbc524c0fb799ab50b", "native_theme_unittests": "f689ea9cbcf20e4980e94433a2ef6954023b082a", "net_unittests": "618821cc684e95e942ff41526f4f2aaf6687cb91", "pdf_unittests": "785913c06cc5f0a56c7a3fb8eb053db51f339ebb", "perfetto_unittests": "f34fc79ab0f078cc2fdbfb5857bb50d3a864d678", "ppapi_unittests": "569165ffc9fe48839de8e89e05a5c2d7c8894ee5", "printing_unittests": "b9da9d66be5db2e055b44a7048af3e0b2db0c92f", "remoting_unittests": "0b3b5c49b475973ec840d502bb4d02de934ce212", "sandbox_mac_unittests": "842cf4ea5ce167fb98a442400ff10fcf9c1c3322", "service_manager_unittests": "98a20d71af4f7ad0599922c7d632d159bc90ef9f", "services_unittests": "1363629efea1d771d62e778948641564ca7a547a", "shell_dialogs_unittests": "9c60b80a4830422db2f88f9b6e68e1251bb1734d", "skia_unittests": "bf1b92076429317c40eb285e9bc9a188d7995235", "snapshot_unittests": "aebd826d417b24e581067480d3d701c6173aedea", "sql_unittests": "2529c7688048d3da0e6c707944bae4b132e722cd", "storage_unittests": "671b6b16953553f98b212fbf79aa5f9bdfc8f723", "sync_integration_tests": "f05a7e4a0bebc43689530bd74cd19e6a248f0f77", "ui_base_unittests": "438b9adaa05ea6ae97514b48adfd540ab05c2cae", "ui_touch_selection_unittests": "33bcea04d9174b9ee389491e1aa16d9ef187471d", "unit_tests": "69d0cc368ef7e489847ec88e62ee94b45c2d465e", "url_unittests": "0b3741f8ba205939421a02b5357290737c913e56", "views_unittests": "a8dee709d4ce7fe28319063cc2ff1d5078239829", "viz_unittests": "a4834f29cb7f908503f020f78a19ee5444a18fc1", "wtf_unittests": "7f50437f17922dc3e11ac1051083497743d45b8d"}}', '--summary-json', '/b/s/w/ir/tmp/t/tmpuSVz_T.json', '--task-output-dir', '/b/s/w/ir/tmp/t/tmpTJDAZD', '-o', '/b/s/w/ir/tmp/t/tmp334yeq.json', '/b/s/w/ir/tmp/t/tmpTJDAZD/44712594aa0cea10/output.json'] in None (env: None) Command ['/b/s/w/ir/cache/vpython/5b0713/bin/python', '/b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "vm258-m9", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1556259839643580, "id": "8915136998344281456", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Mac ASan 64 Tests (1)/52291", "builder:Mac ASan 64 Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2b08a071a2fa53807bdaf7ed61bb249d6294691c", "gitiles_ref:refs/heads/master", "parent_buildername:Mac ASan 64 Builder", "parent_buildnumber:81869", "scheduler_invocation_id:9080567060607902928", "scheduler_job_id:chromium/Mac ASan 64 Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Mac ASan 64 Tests (1)", "buildnumber": 52291, "got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "got_revision_cp": "refs/heads/master@{#654352}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "got_webrtc_revision_cp": "refs/heads/master@{#27778}", "mastername": "chromium.memory", "parent_buildername": "Mac ASan 64 Builder", "parent_got_angle_revision": "6f691fbb59c7d01fbb335294a0c0df7ba9b0fc84", "parent_got_dawn_revision": "ef90079944eb1c7b94f70320203997dced1658b6", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "parent_got_revision_cp": "refs/heads/master@{#654352}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "ba65b118eb24c527a0669d3ce40031b124e6fb20", "parent_got_v8_revision_cp": "refs/heads/7.6.39@{#1}", "parent_got_webrtc_revision": "e9145d65c106e3493c5f7b00c6e58c73536087e0", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27778}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2b08a071a2fa53807bdaf7ed61bb249d6294691c", "swarm_hashes": {"accessibility_unittests": "db778aa035494ea06c64a6e20bbddfbce729fae4", "angle_unittests": "5928cf6eafeb37a47c5f167b8f10c1e34a5d33a9", "app_shell_unittests": "9e46482d3df5020b5843ba69e9a440d08984cbbb", "base_unittests": "10c70501fb003f98251eaa1e11b8aa7da6838773", "blink_common_unittests": "20e5eec4fc1e1803de30b709a219331bd04eb50e", "blink_fuzzer_unittests": "4704974ef2e2575a7de85d49342aa4669cba34b6", "blink_heap_unittests": "a739731193effe75d71e5cb0995fd979f0fbf61a", "blink_platform_unittests": "e8670f472fe8378fb88ace998794db5b9ae6bd0a", "blink_unittests": "fbc870a3b382fe8a45e62af5fc5287aed3e3ef02", "boringssl_crypto_tests": "94d5afdc2c9765339d6982156bec451848e01a40", "boringssl_ssl_tests": "3ef551a5b13e1bd8c2e2de6274e663902b3d0094", "browser_tests": "a9c155120af735723d3012c8c27ef1252cdf9a51", "cacheinvalidation_unittests": "a5ca45f76a7a883b7b5626f71ac94c45c5bebb3f", "capture_unittests": "29560bb2d114a94c24f9570d34c02a4e65b13801", "cast_unittests": "eaa867d783338c7e660e8c4d1e08e527330d01f3", "cc_unittests": "7055d49610cd31088f1d770d2709c7535bac08b0", "chrome_app_unittests": "8418b08d81271deaa4726bcbb5c890a43c5db990", "chromedriver_unittests": "c29536ea65c0f7444a9b74ee2540c50b24e8a386", "components_browsertests": "8ffa6377cacbedd3e8393ede31032df93a4e7d25", "components_unittests": "741bd3be26e122754d169e3bdd9fda014bb4f828", "content_browsertests": "b47cb719a2688ba4d09067bd571a65ef148c81f7", "content_unittests": "83e1b3ae932011426b3e41eebf8232aa1ef15747", "crashpad_tests": "9f5aa5272a521531e9e293434b1f7394636a5a04", "cronet_tests": "811a46c494b386c23547d3ba1b92d2a31215356d", "cronet_unittests": "2d873e63b1337131669d62c871bd85883be46a3d", "crypto_unittests": "d9d70e480a7172f69c2248858bb5c0dc5dcaa7d3", "device_unittests": "858b25dcc589c3b28cdc9deb5ec744116c3d175c", "display_unittests": "a9d4b9f5076d8a6507b833337d0a7aea302ba1db", "events_unittests": "5b7afb83616b3286c5fced88101b7065d5330e47", "extensions_browsertests": "2f95f8f43bcde508a935dda8bae68722de345e51", "extensions_unittests": "e30b59436b74b4857fd5e235fa2fc044ffb17c44", "filesystem_service_unittests": "5e1021099b4a7b8a0eaa9f1846767aecbfab07a0", "gcm_unit_tests": "2e8de3ec399e66ceb787b446ed550df07cfe0720", "gfx_unittests": "70c1a85ef3b0d1e658abe2332a9ca5f0dab442ed", "gin_unittests": "e76ca3101ec9a8ef3774918cc8c160283c1284be", "google_apis_unittests": "8f891803161ebdfd2057b731099283d0f894dc3f", "gpu_unittests": "acc1543f37cc8ba208280c4954f11d6d3a288c95", "headless_browsertests": "2422dfc4c30d1ac4e5f0f71c5339e2ab8f252dfd", "headless_unittests": "409e3db57a9d649108c1860ca6331c0937a5a08d", "interactive_ui_tests": "08a50e4590dd1f881e37f483a4e983fc50600238", "ipc_tests": "18d3186520e212f09d636fb78f7c93d0aae18b69", "jingle_unittests": "e1fc54e615f36b542780d0df4f4b416b948a94fd", "latency_unittests": "ed9a65aaf0d2a6b2fdd2b34d5260f7e908726413", "leveldb_service_unittests": "48ae89a4c0f2a2c68fab7078e9ae5db7f16fbdc1", "libjingle_xmpp_unittests": "dc95cffca67c946940ab835fd90d9f53479ba39c", "media_blink_unittests": "70baa9f66e605c064c29dc6a0916dce72ebb8ca9", "media_service_unittests": "c197cca6393a1c55d8030e291a4474284a2c8b0f", "media_unittests": "31625830ddafe86b50bd1ead646017c659d832b9", "message_center_unittests": "0477d462fcecf815d5b4f3b45ee14db48de8d928", "midi_unittests": "2df3ec5ef9d25f2669941c8a514de48a24627a4a", "mojo_unittests": "3e7e7ad90524693cb1ab4fdbc524c0fb799ab50b", "native_theme_unittests": "f689ea9cbcf20e4980e94433a2ef6954023b082a", "net_unittests": "618821cc684e95e942ff41526f4f2aaf6687cb91", "pdf_unittests": "785913c06cc5f0a56c7a3fb8eb053db51f339ebb", "perfetto_unittests": "f34fc79ab0f078cc2fdbfb5857bb50d3a864d678", "ppapi_unittests": "569165ffc9fe48839de8e89e05a5c2d7c8894ee5", "printing_unittests": "b9da9d66be5db2e055b44a7048af3e0b2db0c92f", "remoting_unittests": "0b3b5c49b475973ec840d502bb4d02de934ce212", "sandbox_mac_unittests": "842cf4ea5ce167fb98a442400ff10fcf9c1c3322", "service_manager_unittests": "98a20d71af4f7ad0599922c7d632d159bc90ef9f", "services_unittests": "1363629efea1d771d62e778948641564ca7a547a", "shell_dialogs_unittests": "9c60b80a4830422db2f88f9b6e68e1251bb1734d", "skia_unittests": "bf1b92076429317c40eb285e9bc9a188d7995235", "snapshot_unittests": "aebd826d417b24e581067480d3d701c6173aedea", "sql_unittests": "2529c7688048d3da0e6c707944bae4b132e722cd", "storage_unittests": "671b6b16953553f98b212fbf79aa5f9bdfc8f723", "sync_integration_tests": "f05a7e4a0bebc43689530bd74cd19e6a248f0f77", "ui_base_unittests": "438b9adaa05ea6ae97514b48adfd540ab05c2cae", "ui_touch_selection_unittests": "33bcea04d9174b9ee389491e1aa16d9ef187471d", "unit_tests": "69d0cc368ef7e489847ec88e62ee94b45c2d465e", "url_unittests": "0b3741f8ba205939421a02b5357290737c913e56", "views_unittests": "a8dee709d4ce7fe28319063cc2ff1d5078239829", "viz_unittests": "a4834f29cb7f908503f020f78a19ee5444a18fc1", "wtf_unittests": "7f50437f17922dc3e11ac1051083497743d45b8d"}}', '--summary-json', '/b/s/w/ir/tmp/t/tmpuSVz_T.json', '--task-output-dir', '/b/s/w/ir/tmp/t/tmpTJDAZD', '-o', '/b/s/w/ir/tmp/t/tmp334yeq.json', '/b/s/w/ir/tmp/t/tmpTJDAZD/44712594aa0cea10/output.json'] returned exit code 0