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

python -u /b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py --show-path --with-third-party-lib -- python /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py --verbose -o /b/swarming/w/ir/tmp/t/tmpOgWTOj.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpEI4Iqe --merge-script /b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmp9EQOZzmerge_script_log --merge-additional-args '["--bucket", "chromium-result-details", "--test-name", "cacheinvalidation_unittests"]' --build-properties '{"bot_id": "swarm99-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555800323689632, "id": "8915618835745360144", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Lollipop Tablet Tester/13427", "builder:Lollipop Tablet Tester", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:41254", "scheduler_invocation_id:9081048897806617888", "scheduler_job_id:chromium/Lollipop Tablet Tester", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Lollipop Tablet Tester", "buildnumber": 13427, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "got_revision_cp": "refs/heads/master@{#652776}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "parent_got_revision_cp": "refs/heads/master@{#652776}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "swarm_hashes": {"android_webview_unittests": "9a856695652e57dd319e2efadd3e77d11c52ea8d", "angle_unittests": "1a6de6ee001f40eae5f1959f158102c257186b49", "base_unittests": "f052ba2ffb2e14f745e931f02008eab58bc00af7", "blink_common_unittests": "cc780758682b951b55db433cae965f406ef938a8", "blink_heap_unittests": "2bec1aaeff4a8922488ac4bf9e36152b7477e9a8", "blink_platform_unittests": "5fbea2da05fd7c85571e139e8e81beda6c853450", "blink_unittests": "fe6240746171504e35af2cd14280fa41ea08d65a", "blink_web_tests_exparchive": "5922e3086b6ab592e5f1f1dc539eeb1a6915a998", "boringssl_crypto_tests": "ea46dd9dd17c8b072d40952ffa3d8c2208aea58a", "boringssl_ssl_tests": "a1e972f0f49dcc1993cb70ee8e7d7ffeba232854", "breakpad_unittests": "2f109110a9f7dd384fa6d53ffeab368ddf1f06c0", "cacheinvalidation_unittests": "d1e211e4d2e63910ac457f809f8370e3c3de99ed", "capture_unittests": "dc05bb9dd60a79745b65fffc6af08b0c53c0e602", "cast_unittests": "b96fce0cfb03b34c8069ccf404309254883086bd", "cc_unittests": "86941b020f4feea3641acdacb2f448c468cc36da", "chrome_public_test_apk": "b405da64270ce357069a0bd45c4e511202c83a5e", "chrome_public_test_vr_apk": "921c595b721c5bcb34db8302b4b1f7fdb7ead7c6", "components_browsertests": "249682c2ddd0f7a836afc78a51d99e7a7d11a55e", "components_unittests": "3b39fc94d16e93eef3a19a5d42ded6994f2a402a", "content_browsertests": "25ad73e7e864328242caef5584ee13bdabbbc684", "content_shell_test_apk": "77040a1313cb71f31cfc4a1f3b8348158fb3f3d2", "content_unittests": "6dba0580d81134d3aff852078385a1ecbfb21149", "crypto_unittests": "79917fb2491a16ea71f4cbea50bd1b4b79d1a1e7", "device_unittests": "a3f47125b671e5184a9bc328076039d52fc06a26", "display_unittests": "52c9a2702b5e8ad1c1bf6cc41907eadb9a6052aa", "events_unittests": "990fe92479802cb76130305b513b9b6d3321bdd1", "gcm_unit_tests": "a2793bed54a6209201ce62b03071f3f1fb8d056f", "gfx_unittests": "939159119a3c414e9f4954e1cd9c28a484e08ace", "gin_unittests": "a9740cf8613663f3175dc3091be7bc6bb7136115", "gl_tests": "b31deacda208738e5839761816b999a6becb07e0", "gl_unittests": "8059ca1e5c33dc3701083862d613c020be5e0b8b", "google_apis_unittests": "8e2f1f7bf18aecbbfc80aac081c23c2724ad9eaf", "gpu_unittests": "c7c88c12de92a86770cb752e2be6481396245fa9", "ipc_tests": "3d8588e0c823ca8ad663abc07beca6a6fe60b248", "jingle_unittests": "62f7379f0448dcccc1c2c0402a266b2771e5eca5", "latency_unittests": "6ae75b591d7b33672425e40626d0bfc73481af66", "libjingle_xmpp_unittests": "3f4d0d7f43a6e23412d593900690b19e6a3a2cc5", "media_blink_unittests": "4cc952dd35068102681431b3fbca62ecf8a9b6a5", "media_service_unittests": "67c072e3a41911c779852962c18ec137ed76262a", "media_unittests": "10ed03ae898e608539d26bc91f3d10e380f053d5", "midi_unittests": "7b1172fadbb576c74d1ce12309585d2c61a2e916", "mojo_test_apk": "d075739cd4519b80d8c9c20c9cd462e25a011123", "mojo_unittests": "811dce70da275092a427ad490ef789fa56dd8df0", "net_unittests": "b488d600147ce29c7e3cf60b350a2b329b08de34", "sandbox_linux_unittests": "524e78ac45f832a0b59c794ef29db71ddd6d81c4", "services_unittests": "3f1e1585d25bef31643918e009dade1292b1cd01", "shell_dialogs_unittests": "0d1e600e9547206ec8900d5515764a381f04fa78", "skia_unittests": "a2010cf89044eccf924402568ae844439d984cd4", "sql_unittests": "01b65beeca3bef9cb914231119ca85a38a9ce6eb", "storage_unittests": "39d0d4e04e3b9e611008d7d53be9e73815631d04", "system_webview_shell_layout_test_apk": "f50a7dd93161a5db0c3eec6ab5df159f39a14a69", "ui_android_unittests": "f76e28cc0d924e1e8175f0157a1d37ecbf9bf845", "ui_base_unittests": "617265d5e8f51bfd35eeba7952a79bad796e9e81", "ui_touch_selection_unittests": "86cfd605471e2f9649dedecb77d4ba4e05a6e9fe", "unit_tests": "bcea0154442d20710ae29edede782f73a8014572", "url_unittests": "52c16e0d3f3f05a8648a719286add96e54000506", "viz_unittests": "5d163ba4a11f67f84db191a7e6886148ba5c52c1", "vr_android_unittests": "9f69fdfacc208130560ec49aa0b3a2359c2f6e5b", "vr_common_unittests": "72d7d225bd1243c9d25d2b4299e3d6150c2c9378", "vr_pixeltests": "e7ce4f24bb2bd78f2cc67ad079be06b7f89a3dee", "webview_cts_tests": "1b13bc6bbb49038f6c1eb8c97490f62a87ad8c00", "webview_instrumentation_test_apk": "298e70b24932c967f00c9bee588590be3b2d093e", "webview_ui_test_app_test_apk": "832b6ba3e18211e471e3e730576baf4e50345347", "wtf_unittests": "e7095fffa5f13932b92cbd9c0096bf2b188be415"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmpLK1BMU.json -- swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/swarming/w/ir/tmp/t/tmpvPnG6T.json in dir /b/swarming/w/ir/k: allow_subannotations: True cmd: ['python', '-u', '/b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py', '--show-path', '--with-third-party-lib', '--', 'python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py', '--verbose', '-o', '/b/swarming/w/ir/tmp/t/tmpOgWTOj.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpEI4Iqe', '--merge-script', '/b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmp9EQOZzmerge_script_log', '--merge-additional-args', '["--bucket", "chromium-result-details", "--test-name", "cacheinvalidation_unittests"]', '--build-properties', '{"bot_id": "swarm99-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555800323689632, "id": "8915618835745360144", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Lollipop Tablet Tester/13427", "builder:Lollipop Tablet Tester", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:41254", "scheduler_invocation_id:9081048897806617888", "scheduler_job_id:chromium/Lollipop Tablet Tester", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Lollipop Tablet Tester", "buildnumber": 13427, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "got_revision_cp": "refs/heads/master@{#652776}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "parent_got_revision_cp": "refs/heads/master@{#652776}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "swarm_hashes": {"android_webview_unittests": "9a856695652e57dd319e2efadd3e77d11c52ea8d", "angle_unittests": "1a6de6ee001f40eae5f1959f158102c257186b49", "base_unittests": "f052ba2ffb2e14f745e931f02008eab58bc00af7", "blink_common_unittests": "cc780758682b951b55db433cae965f406ef938a8", "blink_heap_unittests": "2bec1aaeff4a8922488ac4bf9e36152b7477e9a8", "blink_platform_unittests": "5fbea2da05fd7c85571e139e8e81beda6c853450", "blink_unittests": "fe6240746171504e35af2cd14280fa41ea08d65a", "blink_web_tests_exparchive": "5922e3086b6ab592e5f1f1dc539eeb1a6915a998", "boringssl_crypto_tests": "ea46dd9dd17c8b072d40952ffa3d8c2208aea58a", "boringssl_ssl_tests": "a1e972f0f49dcc1993cb70ee8e7d7ffeba232854", "breakpad_unittests": "2f109110a9f7dd384fa6d53ffeab368ddf1f06c0", "cacheinvalidation_unittests": "d1e211e4d2e63910ac457f809f8370e3c3de99ed", "capture_unittests": "dc05bb9dd60a79745b65fffc6af08b0c53c0e602", "cast_unittests": "b96fce0cfb03b34c8069ccf404309254883086bd", "cc_unittests": "86941b020f4feea3641acdacb2f448c468cc36da", "chrome_public_test_apk": "b405da64270ce357069a0bd45c4e511202c83a5e", "chrome_public_test_vr_apk": "921c595b721c5bcb34db8302b4b1f7fdb7ead7c6", "components_browsertests": "249682c2ddd0f7a836afc78a51d99e7a7d11a55e", "components_unittests": "3b39fc94d16e93eef3a19a5d42ded6994f2a402a", "content_browsertests": "25ad73e7e864328242caef5584ee13bdabbbc684", "content_shell_test_apk": "77040a1313cb71f31cfc4a1f3b8348158fb3f3d2", "content_unittests": "6dba0580d81134d3aff852078385a1ecbfb21149", "crypto_unittests": "79917fb2491a16ea71f4cbea50bd1b4b79d1a1e7", "device_unittests": "a3f47125b671e5184a9bc328076039d52fc06a26", "display_unittests": "52c9a2702b5e8ad1c1bf6cc41907eadb9a6052aa", "events_unittests": "990fe92479802cb76130305b513b9b6d3321bdd1", "gcm_unit_tests": "a2793bed54a6209201ce62b03071f3f1fb8d056f", "gfx_unittests": "939159119a3c414e9f4954e1cd9c28a484e08ace", "gin_unittests": "a9740cf8613663f3175dc3091be7bc6bb7136115", "gl_tests": "b31deacda208738e5839761816b999a6becb07e0", "gl_unittests": "8059ca1e5c33dc3701083862d613c020be5e0b8b", "google_apis_unittests": "8e2f1f7bf18aecbbfc80aac081c23c2724ad9eaf", "gpu_unittests": "c7c88c12de92a86770cb752e2be6481396245fa9", "ipc_tests": "3d8588e0c823ca8ad663abc07beca6a6fe60b248", "jingle_unittests": "62f7379f0448dcccc1c2c0402a266b2771e5eca5", "latency_unittests": "6ae75b591d7b33672425e40626d0bfc73481af66", "libjingle_xmpp_unittests": "3f4d0d7f43a6e23412d593900690b19e6a3a2cc5", "media_blink_unittests": "4cc952dd35068102681431b3fbca62ecf8a9b6a5", "media_service_unittests": "67c072e3a41911c779852962c18ec137ed76262a", "media_unittests": "10ed03ae898e608539d26bc91f3d10e380f053d5", "midi_unittests": "7b1172fadbb576c74d1ce12309585d2c61a2e916", "mojo_test_apk": "d075739cd4519b80d8c9c20c9cd462e25a011123", "mojo_unittests": "811dce70da275092a427ad490ef789fa56dd8df0", "net_unittests": "b488d600147ce29c7e3cf60b350a2b329b08de34", "sandbox_linux_unittests": "524e78ac45f832a0b59c794ef29db71ddd6d81c4", "services_unittests": "3f1e1585d25bef31643918e009dade1292b1cd01", "shell_dialogs_unittests": "0d1e600e9547206ec8900d5515764a381f04fa78", "skia_unittests": "a2010cf89044eccf924402568ae844439d984cd4", "sql_unittests": "01b65beeca3bef9cb914231119ca85a38a9ce6eb", "storage_unittests": "39d0d4e04e3b9e611008d7d53be9e73815631d04", "system_webview_shell_layout_test_apk": "f50a7dd93161a5db0c3eec6ab5df159f39a14a69", "ui_android_unittests": "f76e28cc0d924e1e8175f0157a1d37ecbf9bf845", "ui_base_unittests": "617265d5e8f51bfd35eeba7952a79bad796e9e81", "ui_touch_selection_unittests": "86cfd605471e2f9649dedecb77d4ba4e05a6e9fe", "unit_tests": "bcea0154442d20710ae29edede782f73a8014572", "url_unittests": "52c16e0d3f3f05a8648a719286add96e54000506", "viz_unittests": "5d163ba4a11f67f84db191a7e6886148ba5c52c1", "vr_android_unittests": "9f69fdfacc208130560ec49aa0b3a2359c2f6e5b", "vr_common_unittests": "72d7d225bd1243c9d25d2b4299e3d6150c2c9378", "vr_pixeltests": "e7ce4f24bb2bd78f2cc67ad079be06b7f89a3dee", "webview_cts_tests": "1b13bc6bbb49038f6c1eb8c97490f62a87ad8c00", "webview_instrumentation_test_apk": "298e70b24932c967f00c9bee588590be3b2d093e", "webview_ui_test_app_test_apk": "832b6ba3e18211e471e3e730576baf4e50345347", "wtf_unittests": "e7095fffa5f13932b92cbd9c0096bf2b188be415"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmpLK1BMU.json', '--', 'swarming', 'collect', '-server', 'https://chromium-swarm.appspot.com', '-worker', '50', '-task-summary-python', '-task-output-stdout', 'all', '-verbose', '-requests-json', '/b/swarming/w/ir/tmp/t/tmpvPnG6T.json'] env: {'CHROME_HEADLESS': '1', 'PATH': '/b/swarming/w/ir/cache/builder/src/third_party/android_tools/sdk/platform-tools:/b/swarming/w/ir/cache/builder/src/build/android:%(PATH)s'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests on Android device Nexus 7 [2013]',) ok_ret: ALL_OK step_test_data: gen_default_step_test_data(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 43919 DOCKER_CONFIG: /b/swarming/w/ir/tmp/docker_cfg_task DOCKER_TMPDIR: /b/swarming/w/ir/tmp/docker_tmp_task GIT_CONFIG_NOSYSTEM: 1 GIT_TERMINAL_PROMPT: 0 HOME: /home/chrome-bot IFACE: eth0 INFRA_GIT_WRAPPER_HOME: /b/swarming/w/ir/tmp/git_home_task LOGDOG_COORDINATOR_HOST: logs.chromium.org LOGDOG_STREAM_PREFIX: buildbucket/cr-buildbucket.appspot.com/8915618835745360144 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/it8JRhCM/luci_context.403624987 MAC_CHROMIUM_TMPDIR: /b/swarming/w/ir/tmp/t METHOD: dhcp NO_GCE_CHECK: False PATH: /b/swarming/w/ir/cache/swarming_client:/b/swarming/w/ir/cache/builder/src/third_party/android_tools/sdk/platform-tools:/b/swarming/w/ir/cache/builder/src/build/android:/b/swarming/w/ir/cipd_bin_packages:/b/swarming/w/ir/cipd_bin_packages/bin:/b/swarming/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin PWD: /b/swarming/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 ROOT_SETUP_LOG: /var/log/messages/chromebuild/root-setup.log SHLVL: 1 STARTUP_LOG: /var/log/messages/chromebuild/startup.log SWARMING_BOT_ID: swarm99-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 4455be820af87d11 TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TERM: linux TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t UPSTART_EVENTS: net-device-up UPSTART_INSTANCE: UPSTART_JOB: chromebuild-startup USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-04-20 16:43:20,295 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpEI4Iqe' 2019-04-20 16:43:20,295 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpEI4Iqe' already exists! 2019-04-20 16:43:20,296 - root: [WARNING] task_output_dir existing content: [] 2019-04-20 16:43:20,296 - root: [INFO] collect_cmd: swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/swarming/w/ir/tmp/t/tmpvPnG6T.json -output-dir /b/swarming/w/ir/tmp/t/tmpEI4Iqe -task-summary-json /b/swarming/w/ir/tmp/t/tmpLK1BMU.json [D2019-04-20T16:43:20.301953-07:00 28467 0 auth.go:1265] Minting a new token {"key":"luci_ctx/8cbb2cdc658377d8e3c3df2e89f409992ea64d81925f91a8a7cb99d78badf76b", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-20T16:43:20.302026-07:00 28467 0 luci_ctx.go:138] POST http://127.0.0.1:33548/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/8cbb2cdc658377d8e3c3df2e89f409992ea64d81925f91a8a7cb99d78badf76b", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-20T16:43:20.303900-07:00 28467 0 auth.go:1222] Token expires in 28m9.696166055s {"key":"luci_ctx/8cbb2cdc658377d8e3c3df2e89f409992ea64d81925f91a8a7cb99d78badf76b", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-20T16:43:21.616508-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:22.909280-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:24.232491-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:25.591127-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:27.113568-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:28.457343-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:29.859994-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:31.329112-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:32.815946-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:34.321082-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:36.058325-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:37.667520-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:39.371431-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:41.094521-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:42.923337-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:44.773721-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:46.694791-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:48.700574-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:50.773640-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:52.918614-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:55.155351-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:57.449370-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:43:59.786660-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 [D2019-04-20T16:44:02.352640-07:00 28467 0 collect.go:344] Waiting task_id: 4455f3869b602610 4455f3869b602610: exit 0 /b/swarming/swarming_bot.1.zip/third_party/requests/__init__.py:83: RequestsDependencyWarning: Old version of cryptography ([1, 2, 3]) may cause slowdown. Additional test environment: CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 LANG=en_US.UTF-8 Command: /b/swarming/w/ir/.swarming_module_cache/vpython/3bcbb9/bin/python ../../build/android/test_wrapper/logdog_wrapper.py --target cacheinvalidation_unittests --logdog-bin-cmd ../../bin/logdog_butler --store-tombstones --gs-results-bucket=chromium-result-details --recover-devices --test-launcher-summary-output=/b/swarming/w/iof2iXfZ/output.json I 0.000s Main command: bin/../../../build/android/test_runner.py gtest --output-directory bin/../. --runtime-deps-path bin/../gen.runtime/third_party/cacheinvalidation/cacheinvalidation_unittests__test_runner_script.runtime_deps --suite cacheinvalidation_unittests -v --store-tombstones --gs-results-bucket=chromium-result-details --recover-devices --test-launcher-summary-output=/b/swarming/w/iof2iXfZ/output.json I 0.007s Main condition '<lambda>' met I 0.008s Main condition '<lambda>' met I 3.134s TimeoutThread-1-for-prepare_device(0498a8ab) condition 'sd_card_ready' met (0.0s) I 3.496s TimeoutThread-1-for-prepare_device(0498a8ab) condition 'pm_ready' met (0.4s) I 3.514s TimeoutThread-1-for-prepare_device(0498a8ab) condition 'boot_completed' met (0.4s) I 11.119s calculate_device_checksums condition '<lambda>' met (0.1s) I 12.836s list_tests(0498a8ab) flags: I 12.836s list_tests(0498a8ab) --gtest_list_tests I 14.272s list_tests(0498a8ab) /storage/emulated/legacy/temp_file-4f5954aa73cd.gtest_out size on device: 682 I 14.339s Main Using external sharding settings. This is shard 0/1 I 14.339s Main STARTING TRY #1/3 I 14.340s Main Will run 28 tests on 1 devices: 0498a8ab W 14.404s run_tests_on_device(0498a8ab) No tombstones to clear. I 24.917s run_tests_on_device(0498a8ab) flags: I 24.917s run_tests_on_device(0498a8ab) Getting logdog client. I 26.586s run_tests_on_device(0498a8ab) /storage/emulated/legacy/temp_file-4bfe1070a5614.gtest_out size on device: 96227 I 26.753s run_tests_on_device(0498a8ab) Logcat saved to https://luci-logdog.appspot.com/v/?s=chromium%2Fandroid%2Fswarming%2Flogcats%2F4455f3869b602611%2F%2B%2Flogcat_logcat_-2631999291401687399_20190420T234357-UTC_0498a8ab I 26.754s archive Writing text to logdog stream, logcat_logcat_-2631999291401687399_20190420T234357-UTC_0498a8ab I 27.260s run_tests_on_device(0498a8ab) >>ScopedMainEntryLogger I 27.260s run_tests_on_device(0498a8ab) Note: Google Test filter = InvalidationClientImplTest.GenerateNonce:InvalidationClientImplTest.Heartbeats:InvalidationClientImplTest.IncomingAuthErrorMessage:InvalidationClientImplTest.IncomingErrorMessage:InvalidationClientImplTest.Invalidations:InvalidationClientImplTest.NetworkTimeouts:InvalidationClientImplTest.NoRegistrationSummary:InvalidationClientImplTest.Register:InvalidationClientImplTest.ServerRequests:InvalidationClientImplTest.Start:ProtocolHandlerTest.ConfigMessage:ProtocolHandlerTest.ErrorMessage:ProtocolHandlerTest.IncomingCompositeMessage:ProtocolHandlerTest.InvalidInboundMessage:ProtocolHandlerTest.InvalidOutboundMessage:ProtocolHandlerTest.MajorVersionMismatch:ProtocolHandlerTest.MinorVersionMismatch:ProtocolHandlerTest.ReceiveTokenControlOnly:ProtocolHandlerTest.SendInitializeOnly:ProtocolHandlerTest.SendMultipleMessageTypes:ProtocolHandlerTest.TokenMismatch:ProtocolHandlerTest.TokenMissing:ProtocolHandlerTest.UnparseableInboundMessage:RecurringTaskTest.ExponentialBackoffTask:RecurringTaskTest.OneShotTask:RecurringTaskTest.PeriodicTask:ThrottleTest.ThrottlingScripted:ThrottleTest.ThrottlingStorm I 27.260s run_tests_on_device(0498a8ab) [==========] Running 28 tests from 4 test suites. I 27.260s run_tests_on_device(0498a8ab) [----------] Global test environment set-up. I 27.260s run_tests_on_device(0498a8ab) [----------] 10 tests from InvalidationClientImplTest I 27.260s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.Start I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1227197351) Enqueuing 0xc926000 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566362593) Enqueuing 0xc926000 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.260s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.260s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.260s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.260s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.260s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1993457354423810429" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.260s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349468 with a delay -1094689880, Now = 500000 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.260s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.260s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.260s run_tests_on_device(0498a8ab) [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: "1993457354423810429" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.260s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.261s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1993457354423810429" 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" } } I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1993457354423810429" I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.261s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680316 with a delay -1094689936, Now = 1200000000 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.261s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094689936, Now = 0 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [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 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.261s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.Start (14 ms) I 27.261s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.GenerateNonce I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.261s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.GenerateNonce (2 ms) I 27.261s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.Register I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1266659784) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.261s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.261s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.261s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "51344781347580230" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.261s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349468 with a delay -1094690144, Now = 500000 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.261s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.261s run_tests_on_device(0498a8ab) [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: "51344781347580230" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.261s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.262s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "51344781347580230" 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" } } I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "51344781347580230" I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.262s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680316 with a delay -1094690200, Now = 1200000000 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.262s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690200, Now = 0 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [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 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689264) Enqueuing 0xc9ac470 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9ac470 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 I 27.262s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling -1263349468 with a delay 3376896, Now = 500000 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9ac470 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling -1263397504 with a delay -1266133692, Now = 60000000 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9ac470 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xca26590 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.262s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 27.262s run_tests_on_device(0498a8ab) [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 } } } I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263345336) Enqueuing 0xca26590 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 27.262s run_tests_on_device(0498a8ab) [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 } } } } I 27.262s run_tests_on_device(0498a8ab) [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 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 27.262s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.Register (20 ms) I 27.262s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.Invalidations I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: 107792) Enqueuing 0xc926000 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.262s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.262s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.262s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.263s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.263s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1306237159935227682" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.263s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349300 with a delay -1094690176, Now = 500000 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.263s run_tests_on_device(0498a8ab) [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: "-1306237159935227682" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.263s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1306237159935227682" 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" } } I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1306237159935227682" I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.263s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680124 with a delay -1094690232, Now = 1200000000 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.263s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690232, Now = 0 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [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 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1196346108) Enqueuing 0xc9ac470 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 27.263s run_tests_on_device(0498a8ab) [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 } } } I 27.263s run_tests_on_device(0498a8ab) [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 I 27.263s run_tests_on_device(0498a8ab) [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" } I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566133175) Enqueuing 0xc9b87c0 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566133175) Enqueuing 0xc9b87c0 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566133175) Enqueuing 0xc9b87c0 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9b87c0 I 27.263s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling -1263349300 with a delay -1227387683, Now = 500000 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9b87c0 with delay 181 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9b87c0 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9b87c0 I 27.263s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xca328e0 I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.263s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.263s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 27.264s run_tests_on_device(0498a8ab) [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 } } } I 27.264s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.Invalidations (22 ms) I 27.264s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.ServerRequests I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689208) Enqueuing 0xc926000 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.264s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.264s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.264s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-489552780656402624" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.264s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349300 with a delay -1094690032, Now = 500000 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.264s run_tests_on_device(0498a8ab) [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: "-489552780656402624" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.264s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-489552780656402624" 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" } } I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-489552780656402624" I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.264s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680060 with a delay -1094690088, Now = 1200000000 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.264s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690088, Now = 0 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [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 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.264s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689358) Enqueuing 0xc9ac470 with delay 181 I 27.264s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 27.264s run_tests_on_device(0498a8ab) [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 } } I 27.264s run_tests_on_device(0498a8ab) [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 I 27.264s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(294)] Adding subtree: { } I 27.265s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling -1263349300 with a delay -1094690056, Now = 500000 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9ac470 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 27.265s run_tests_on_device(0498a8ab) [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 } I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.265s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 27.265s run_tests_on_device(0498a8ab) [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 } } I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 27.265s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.ServerRequests (17 ms) I 27.265s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565364983) Enqueuing 0xc926000 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.265s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.265s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.265s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1882228228122174084" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.265s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349300 with a delay -1094689992, Now = 500000 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.265s run_tests_on_device(0498a8ab) [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: "1882228228122174084" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.265s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1882228228122174084" 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" } } I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1882228228122174084" I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.265s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680124 with a delay -1094690048, Now = 1200000000 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.265s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.265s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690048, Now = 0 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.265s run_tests_on_device(0498a8ab) [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 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.265s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177693) Enqueuing 0xc9ac470 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 27.266s run_tests_on_device(0498a8ab) [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" } } I 27.266s run_tests_on_device(0498a8ab) [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 I 27.266s run_tests_on_device(0498a8ab) [ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 27.266s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.IncomingErrorMessage (13 ms) I 27.266s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565364983) Enqueuing 0xc926000 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.266s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.266s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.266s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-9168715198461956805" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.266s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349300 with a delay -1266659784, Now = 500000 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.266s run_tests_on_device(0498a8ab) [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: "-9168715198461956805" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.266s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-9168715198461956805" 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" } } I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-9168715198461956805" I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.266s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680060 with a delay -1094690176, Now = 1200000000 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.266s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.266s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690176, Now = 0 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [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 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.266s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.266s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689240) Enqueuing 0xc9ac470 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9ac470 I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 27.267s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling -1263349300 with a delay 1535216511, Now = 500000 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9ac470 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling -1263397504 with a delay -1266133692, Now = 60000000 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9ac470 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xca26590 I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.267s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 27.267s run_tests_on_device(0498a8ab) [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 } } } I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177693) Enqueuing 0xca26590 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 27.267s run_tests_on_device(0498a8ab) [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" } } I 27.267s run_tests_on_device(0498a8ab) [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 I 27.267s run_tests_on_device(0498a8ab) [ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message I 27.267s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 27.267s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (16 ms) I 27.267s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.NetworkTimeouts I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689208) Enqueuing 0xc926000 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.267s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.267s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.267s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8510640596487870612" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.267s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349300 with a delay -1094690032, Now = 500000 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.267s run_tests_on_device(0498a8ab) [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: "8510640596487870612" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.267s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.267s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8510640596487870612" 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" } } I 27.267s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8510640596487870612" I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.268s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680124 with a delay -1094690088, Now = 1200000000 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.268s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690088, Now = 0 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [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 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689152) Enqueuing 0xc9ac470 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9ac470 I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 27.268s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling -1263349300 with a delay 1535216511, Now = 500000 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9ac470 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling -1263397536 with a delay -1266133692, Now = 60000000 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9ac470 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xca26590 I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.268s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 27.268s run_tests_on_device(0498a8ab) [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 } } } I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xd3297a0 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0x1025e700 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0x102e4b70 I 27.268s run_tests_on_device(0498a8ab) [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 I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true I 27.268s run_tests_on_device(0498a8ab) [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 } I 27.268s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1263349300 with a delay -1094690072, Now = 500000 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x102e4b70 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397536 with a delay 0, Now = 60000000 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x102e4b70 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0x1035ec90 I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.268s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 27.268s run_tests_on_device(0498a8ab) [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 } } I 27.268s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.NetworkTimeouts (20 ms) I 27.268s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689216) Enqueuing 0xc926000 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.268s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.268s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.269s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.269s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.269s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2902369628874123118" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.269s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349412 with a delay -1094690040, Now = 500000 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.269s run_tests_on_device(0498a8ab) [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: "2902369628874123118" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.269s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2902369628874123118" 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" } } I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2902369628874123118" I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.269s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680060 with a delay -1094690096, Now = 1200000000 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.269s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690096, Now = 0 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [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 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263587616) Enqueuing 0xc9ac470 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 27.269s run_tests_on_device(0498a8ab) [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" } } I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 27.269s run_tests_on_device(0498a8ab) [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" } } I 27.269s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.NoRegistrationSummary (12 ms) I 27.269s run_tests_on_device(0498a8ab) [ RUN ] InvalidationClientImplTest.Heartbeats I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567165553) Enqueuing 0xc926000 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689176) Enqueuing 0xc926000 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.269s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566061653) Enqueuing 0xc926000 with delay 181 I 27.269s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.269s run_tests_on_device(0498a8ab) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567324392) Enqueuing 0xc926000 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263401216 with a delay -1227387727, Now = 0 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc926000 I 27.270s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1683924098773374738" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1263349412 with a delay -1094690000, Now = 500000 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401216 with a delay -2147483632, Now = 60000000 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1264084048) Running task 0xc9a0120 I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 27.270s run_tests_on_device(0498a8ab) [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: "-1683924098773374738" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565177461) Enqueuing 0xc9a0120 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.270s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1683924098773374738" 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" } } I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1683924098773374738" I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1263680124 with a delay -1094690056, Now = 1200000000 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1263401200 with a delay -1094690056, Now = 0 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [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 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565983849) Enqueuing 0xc9a0120 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401200 with a delay 0, Now = 10000000 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc9a0120 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xd3297a0 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x1025e700 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x54208d20 I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 27.270s run_tests_on_device(0498a8ab) [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 } I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1263349412 with a delay -1094690072, Now = 500000 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x54208d20 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263680124 with a delay 12, Now = 1200000000 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x54208d20 with delay 181 I 27.270s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x54282e40 I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.270s run_tests_on_device(0498a8ab) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 27.270s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 27.270s run_tests_on_device(0498a8ab) [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 } } I 27.270s run_tests_on_device(0498a8ab) [ OK ] InvalidationClientImplTest.Heartbeats (28 ms) I 27.270s run_tests_on_device(0498a8ab) [----------] 10 tests from InvalidationClientImplTest (165 ms total) I 27.270s run_tests_on_device(0498a8ab) I 27.271s run_tests_on_device(0498a8ab) [----------] 13 tests from ProtocolHandlerTest I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.SendInitializeOnly I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1266659784) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1565364983) Running task 0xc926000 I 27.271s run_tests_on_device(0498a8ab) [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 } I 27.271s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1263349580 with a delay -1094689968, Now = 500000 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1565364983) Running task 0xc9a0120 I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.SendInitializeOnly (3 ms) I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly I 27.271s run_tests_on_device(0498a8ab) [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" } } I 27.271s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566435179) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1566435179) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1264083856) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1264083848) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1264083840) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1262484896) Running task 0xc926000 I 27.271s run_tests_on_device(0498a8ab) [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 } I 27.271s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1263349580 with a delay -1094690400, Now = 500000 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1262484896) Running task 0xc926000 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1262484896) Running task 0xc926000 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1262484896) Running task 0xc926000 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1262484896) Running task 0xc926000 I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1262484896) Running task 0xc926000 I 27.271s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } I 27.271s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1262484896) Running task 0xc9a0120 I 27.271s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (6 ms) I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [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" } I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.InvalidInboundMessage (2 ms) I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [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 } } I 27.271s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.MajorVersionMismatch (2 ms) I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch I 27.271s run_tests_on_device(0498a8ab) [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" } } I 27.271s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.MinorVersionMismatch (2 ms) I 27.271s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.ConfigMessage I 27.271s run_tests_on_device(0498a8ab) [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" } } I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1266659760) Enqueuing 0xc926000 with delay 181 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1566413793) Running task 0xc926000 I 27.272s run_tests_on_device(0498a8ab) [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 } I 27.272s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1263349580 with a delay -1094689784, Now = 500000 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1566413793) Running task 0xc9a0120 I 27.272s run_tests_on_device(0498a8ab) [WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 I 27.272s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.ConfigMessage (15 ms) I 27.272s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.ErrorMessage I 27.272s run_tests_on_device(0498a8ab) [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" } } I 27.272s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) I 27.272s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.TokenMismatch I 27.272s run_tests_on_device(0498a8ab) [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" } } I 27.272s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.TokenMismatch (2 ms) I 27.272s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.TokenMissing I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1565950213) Enqueuing 0xc926000 with delay 181 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1566413793) Running task 0xc926000 I 27.272s run_tests_on_device(0498a8ab) [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 } I 27.272s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1263349580 with a delay -1094689616, Now = 500000 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1566413793) Running task 0xc9a0120 I 27.272s run_tests_on_device(0498a8ab) [WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } I 27.272s run_tests_on_device(0498a8ab) [WARNING:protocol-handler.cc(313)] Unable to build message I 27.272s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.TokenMissing (3 ms) I 27.272s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1264083880) Enqueuing 0xc926000 with delay 181 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1566413793) Running task 0xc926000 I 27.272s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling -1263349580 with a delay 63, Now = 500000 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xc926000 with delay 181 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1566413793) Running task 0xc9a0120 I 27.272s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 27.272s run_tests_on_device(0498a8ab) [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 } I 27.272s run_tests_on_device(0498a8ab) [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 } } I 27.272s run_tests_on_device(0498a8ab) [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 } } } I 27.272s run_tests_on_device(0498a8ab) [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 } } } I 27.272s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (4 ms) I 27.272s run_tests_on_device(0498a8ab) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage I 27.272s run_tests_on_device(0498a8ab) [INFO:protocol-handler.cc(139)] Incoming message: { } I 27.272s run_tests_on_device(0498a8ab) [ERROR:ticl-message-validator.cc(361)] required field header missing from { } I 27.272s run_tests_on_device(0498a8ab) [ERROR:protocol-handler.cc(145)] Received invalid message: { } I 27.272s run_tests_on_device(0498a8ab) [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (2 ms) I 27.272s run_tests_on_device(0498a8ab) [----------] 13 tests from ProtocolHandlerTest (47 ms total) I 27.272s run_tests_on_device(0498a8ab) I 27.272s run_tests_on_device(0498a8ab) [----------] 3 tests from RecurringTaskTest I 27.272s run_tests_on_device(0498a8ab) [ RUN ] RecurringTaskTest.PeriodicTask I 27.272s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -1263401856 with a delay -1565375241, Now = 10000 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x0 with delay 0 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x2710 I 27.272s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 10000 I 27.272s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401856 with a delay -1563481368, Now = 60000 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x2710 with delay 0 I 27.272s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x11170 I 27.272s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 70000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401856 with a delay -1563481368, Now = 60000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x11170 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x1fbd0 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 130000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401856 with a delay -1563481368, Now = 60000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x1fbd0 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x2e630 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 190000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401856 with a delay -1563481368, Now = 60000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x2e630 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x3d090 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 250000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401856 with a delay -1563481368, Now = 60000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x3d090 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x4baf0 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 310000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401856 with a delay -1563481368, Now = 60000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x4baf0 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x5a550 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 370000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263401856 with a delay -1563481368, Now = 60000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x5a550 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263397184) Running task 0x68fb0 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689336) Task running: 430000 I 27.273s run_tests_on_device(0498a8ab) [ OK ] RecurringTaskTest.PeriodicTask (7 ms) I 27.273s run_tests_on_device(0498a8ab) [ RUN ] RecurringTaskTest.ExponentialBackoffTask I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -1263397184 with a delay -1263680448, Now = 10000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x0 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0x2710 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 10000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397184 with a delay -1563481368, Now = 50000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x2710 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0xea60 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 60000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397184 with a delay -1563481368, Now = 149000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xea60 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0x33450 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 210000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397184 with a delay -1563481368, Now = 248000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x33450 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0x704e0 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 460000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397184 with a delay -1563481368, Now = 446000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x704e0 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0xde2b0 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 910000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397184 with a delay -1563481368, Now = 842000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0xde2b0 with delay 0 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0x1adb00 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 1760000 I 27.273s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397184 with a delay -1563481368, Now = 1040000 I 27.273s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x1adb00 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0x2ab980 I 27.274s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 2800000 I 27.274s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1263397184 with a delay -1563481368, Now = 1040000 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x2ab980 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396704) Running task 0x3a9800 I 27.274s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689344) Task running: 3840000 I 27.274s run_tests_on_device(0498a8ab) [ OK ] RecurringTaskTest.ExponentialBackoffTask (7 ms) I 27.274s run_tests_on_device(0498a8ab) [ RUN ] RecurringTaskTest.OneShotTask I 27.274s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -1263401904 with a delay 10, Now = 10000 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x0 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263401888) Running task 0x2710 I 27.274s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689368) Task running: 10000 I 27.274s run_tests_on_device(0498a8ab) [INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -1263401904 with a delay 0, Now = 10000 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1567154567) Enqueuing 0x2710 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: -1263396928) Running task 0x4e20 I 27.274s run_tests_on_device(0498a8ab) [INFO:recurring-task_test.cc(71)] (-1094689368) Task running: 20000 I 27.274s run_tests_on_device(0498a8ab) [ OK ] RecurringTaskTest.OneShotTask (3 ms) I 27.274s run_tests_on_device(0498a8ab) [----------] 3 tests from RecurringTaskTest (19 ms total) I 27.274s run_tests_on_device(0498a8ab) I 27.274s run_tests_on_device(0498a8ab) [----------] 2 tests from ThrottleTest I 27.274s run_tests_on_device(0498a8ab) [ RUN ] ThrottleTest.ThrottlingScripted I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263374336) Enqueuing 0x13880 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xe4e1c0 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700 I 27.274s run_tests_on_device(0498a8ab) [ OK ] ThrottleTest.ThrottlingScripted (3 ms) I 27.274s run_tests_on_device(0498a8ab) [ RUN ] ThrottleTest.ThrottlingStorm I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: 2) Enqueuing 0x2710 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xf4240 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x1e8480 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x1e8480 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x2dc6c0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x2dc6c0 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d0900 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x3d0900 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x4c4b40 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x4c4b40 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x5b8d80 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689304) Enqueuing 0x5b8d80 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x3938700 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3a2c940 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x3a2c940 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3b20b80 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x3b20b80 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3c14dc0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x3c14dc0 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d09000 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x3d09000 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3dfd240 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x3dfd240 with delay 0 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3ef1480 I 27.274s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689304) Enqueuing 0x3ef1480 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7270e00 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x7270e00 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7365040 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x7365040 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7459280 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x7459280 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x754d4c0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x754d4c0 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7641700 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x7641700 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7735940 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0x7735940 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7829b80 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689304) Enqueuing 0x7829b80 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaba9500 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xaba9500 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xac9d740 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xac9d740 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xad91980 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xad91980 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xae85bc0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xae85bc0 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaf79e00 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xaf79e00 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb06e040 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xb06e040 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb162280 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689304) Enqueuing 0xb162280 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe4e1c00 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xe4e1c00 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe5d5e40 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xe5d5e40 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe6ca080 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xe6ca080 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe7be2c0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xe7be2c0 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe8b2500 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xe8b2500 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe9a6740 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1263680408) Enqueuing 0xe9a6740 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xea9a980 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(33)] (Now: -1094689304) Enqueuing 0xea9a980 with delay 0 I 27.275s run_tests_on_device(0498a8ab) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x11e1a300 I 27.275s run_tests_on_device(0498a8ab) [ OK ] ThrottleTest.ThrottlingStorm (18 ms) I 27.275s run_tests_on_device(0498a8ab) [----------] 2 tests from ThrottleTest (22 ms total) I 27.275s run_tests_on_device(0498a8ab) I 27.275s run_tests_on_device(0498a8ab) [----------] Global test environment tear-down I 27.275s run_tests_on_device(0498a8ab) [==========] 28 tests from 4 test suites ran. (256 ms total) I 27.275s run_tests_on_device(0498a8ab) [ PASSED ] 28 tests. I 27.275s run_tests_on_device(0498a8ab) <<ScopedMainEntryLogger I 27.278s run_tests_on_device(0498a8ab) Finished running tests on this device. I 27.294s Main FINISHED TRY #1/3 I 27.294s Main All tests completed. C 27.294s Main ******************************************************************************** C 27.294s Main Summary C 27.294s Main ******************************************************************************** C 27.294s Main [==========] 28 tests ran. C 27.294s Main [ PASSED ] 28 tests. C 27.294s Main ******************************************************************************** I 27.295s tear_down_device(0498a8ab) Wrote device cache: /b/swarming/w/ir/out/Debug/device_cache_0498a8ab.json I 27.298s Main Generated json results file at /b/swarming/w/it7L_w2x/tmprwY5Tn I 27.298s Main Finishing archiving output. [W2019-04-20T23:43:59.724861Z 14662 0 butler.go:240] Butler Context was cancelled. Initiating shutdown. {"error":"context canceled"} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' not met [E2019-04-20T23:43:59.751159Z 14662 0 main.go:205] Butler terminated with error. {"error":"context canceled"} [E2019-04-20T23:43:59.751203Z 14662 0 main.go:233] Failed to serve. original error: context canceled [I2019-04-20T23:43:59.751303Z 14662 0 main.go:349] Terminating. {"returnCode":250} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' met 2019-04-20 16:44:02,714 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpEI4Iqe/4455f3869b602610'] 2019-04-20 16:44:02,714 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpEI4Iqe/4455f3869b602610/output.json'] 2019-04-20 16:44:02,714 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py --build-properties {"bot_id": "swarm99-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555800323689632, "id": "8915618835745360144", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Lollipop Tablet Tester/13427", "builder:Lollipop Tablet Tester", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:41254", "scheduler_invocation_id:9081048897806617888", "scheduler_job_id:chromium/Lollipop Tablet Tester", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Lollipop Tablet Tester", "buildnumber": 13427, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "got_revision_cp": "refs/heads/master@{#652776}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "parent_got_revision_cp": "refs/heads/master@{#652776}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "swarm_hashes": {"android_webview_unittests": "9a856695652e57dd319e2efadd3e77d11c52ea8d", "angle_unittests": "1a6de6ee001f40eae5f1959f158102c257186b49", "base_unittests": "f052ba2ffb2e14f745e931f02008eab58bc00af7", "blink_common_unittests": "cc780758682b951b55db433cae965f406ef938a8", "blink_heap_unittests": "2bec1aaeff4a8922488ac4bf9e36152b7477e9a8", "blink_platform_unittests": "5fbea2da05fd7c85571e139e8e81beda6c853450", "blink_unittests": "fe6240746171504e35af2cd14280fa41ea08d65a", "blink_web_tests_exparchive": "5922e3086b6ab592e5f1f1dc539eeb1a6915a998", "boringssl_crypto_tests": "ea46dd9dd17c8b072d40952ffa3d8c2208aea58a", "boringssl_ssl_tests": "a1e972f0f49dcc1993cb70ee8e7d7ffeba232854", "breakpad_unittests": "2f109110a9f7dd384fa6d53ffeab368ddf1f06c0", "cacheinvalidation_unittests": "d1e211e4d2e63910ac457f809f8370e3c3de99ed", "capture_unittests": "dc05bb9dd60a79745b65fffc6af08b0c53c0e602", "cast_unittests": "b96fce0cfb03b34c8069ccf404309254883086bd", "cc_unittests": "86941b020f4feea3641acdacb2f448c468cc36da", "chrome_public_test_apk": "b405da64270ce357069a0bd45c4e511202c83a5e", "chrome_public_test_vr_apk": "921c595b721c5bcb34db8302b4b1f7fdb7ead7c6", "components_browsertests": "249682c2ddd0f7a836afc78a51d99e7a7d11a55e", "components_unittests": "3b39fc94d16e93eef3a19a5d42ded6994f2a402a", "content_browsertests": "25ad73e7e864328242caef5584ee13bdabbbc684", "content_shell_test_apk": "77040a1313cb71f31cfc4a1f3b8348158fb3f3d2", "content_unittests": "6dba0580d81134d3aff852078385a1ecbfb21149", "crypto_unittests": "79917fb2491a16ea71f4cbea50bd1b4b79d1a1e7", "device_unittests": "a3f47125b671e5184a9bc328076039d52fc06a26", "display_unittests": "52c9a2702b5e8ad1c1bf6cc41907eadb9a6052aa", "events_unittests": "990fe92479802cb76130305b513b9b6d3321bdd1", "gcm_unit_tests": "a2793bed54a6209201ce62b03071f3f1fb8d056f", "gfx_unittests": "939159119a3c414e9f4954e1cd9c28a484e08ace", "gin_unittests": "a9740cf8613663f3175dc3091be7bc6bb7136115", "gl_tests": "b31deacda208738e5839761816b999a6becb07e0", "gl_unittests": "8059ca1e5c33dc3701083862d613c020be5e0b8b", "google_apis_unittests": "8e2f1f7bf18aecbbfc80aac081c23c2724ad9eaf", "gpu_unittests": "c7c88c12de92a86770cb752e2be6481396245fa9", "ipc_tests": "3d8588e0c823ca8ad663abc07beca6a6fe60b248", "jingle_unittests": "62f7379f0448dcccc1c2c0402a266b2771e5eca5", "latency_unittests": "6ae75b591d7b33672425e40626d0bfc73481af66", "libjingle_xmpp_unittests": "3f4d0d7f43a6e23412d593900690b19e6a3a2cc5", "media_blink_unittests": "4cc952dd35068102681431b3fbca62ecf8a9b6a5", "media_service_unittests": "67c072e3a41911c779852962c18ec137ed76262a", "media_unittests": "10ed03ae898e608539d26bc91f3d10e380f053d5", "midi_unittests": "7b1172fadbb576c74d1ce12309585d2c61a2e916", "mojo_test_apk": "d075739cd4519b80d8c9c20c9cd462e25a011123", "mojo_unittests": "811dce70da275092a427ad490ef789fa56dd8df0", "net_unittests": "b488d600147ce29c7e3cf60b350a2b329b08de34", "sandbox_linux_unittests": "524e78ac45f832a0b59c794ef29db71ddd6d81c4", "services_unittests": "3f1e1585d25bef31643918e009dade1292b1cd01", "shell_dialogs_unittests": "0d1e600e9547206ec8900d5515764a381f04fa78", "skia_unittests": "a2010cf89044eccf924402568ae844439d984cd4", "sql_unittests": "01b65beeca3bef9cb914231119ca85a38a9ce6eb", "storage_unittests": "39d0d4e04e3b9e611008d7d53be9e73815631d04", "system_webview_shell_layout_test_apk": "f50a7dd93161a5db0c3eec6ab5df159f39a14a69", "ui_android_unittests": "f76e28cc0d924e1e8175f0157a1d37ecbf9bf845", "ui_base_unittests": "617265d5e8f51bfd35eeba7952a79bad796e9e81", "ui_touch_selection_unittests": "86cfd605471e2f9649dedecb77d4ba4e05a6e9fe", "unit_tests": "bcea0154442d20710ae29edede782f73a8014572", "url_unittests": "52c16e0d3f3f05a8648a719286add96e54000506", "viz_unittests": "5d163ba4a11f67f84db191a7e6886148ba5c52c1", "vr_android_unittests": "9f69fdfacc208130560ec49aa0b3a2359c2f6e5b", "vr_common_unittests": "72d7d225bd1243c9d25d2b4299e3d6150c2c9378", "vr_pixeltests": "e7ce4f24bb2bd78f2cc67ad079be06b7f89a3dee", "webview_cts_tests": "1b13bc6bbb49038f6c1eb8c97490f62a87ad8c00", "webview_instrumentation_test_apk": "298e70b24932c967f00c9bee588590be3b2d093e", "webview_ui_test_app_test_apk": "832b6ba3e18211e471e3e730576baf4e50345347", "wtf_unittests": "e7095fffa5f13932b92cbd9c0096bf2b188be415"}} --summary-json /b/swarming/w/ir/tmp/t/tmpLK1BMU.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpEI4Iqe --bucket chromium-result-details --test-name cacheinvalidation_unittests -o /b/swarming/w/ir/tmp/t/tmpOgWTOj.json /b/swarming/w/ir/tmp/t/tmpEI4Iqe/4455f3869b602610/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py', '--build-properties', '{"bot_id": "swarm99-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555800323689632, "id": "8915618835745360144", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Lollipop Tablet Tester/13427", "builder:Lollipop Tablet Tester", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:41254", "scheduler_invocation_id:9081048897806617888", "scheduler_job_id:chromium/Lollipop Tablet Tester", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Lollipop Tablet Tester", "buildnumber": 13427, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "got_revision_cp": "refs/heads/master@{#652776}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "parent_got_revision_cp": "refs/heads/master@{#652776}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "swarm_hashes": {"android_webview_unittests": "9a856695652e57dd319e2efadd3e77d11c52ea8d", "angle_unittests": "1a6de6ee001f40eae5f1959f158102c257186b49", "base_unittests": "f052ba2ffb2e14f745e931f02008eab58bc00af7", "blink_common_unittests": "cc780758682b951b55db433cae965f406ef938a8", "blink_heap_unittests": "2bec1aaeff4a8922488ac4bf9e36152b7477e9a8", "blink_platform_unittests": "5fbea2da05fd7c85571e139e8e81beda6c853450", "blink_unittests": "fe6240746171504e35af2cd14280fa41ea08d65a", "blink_web_tests_exparchive": "5922e3086b6ab592e5f1f1dc539eeb1a6915a998", "boringssl_crypto_tests": "ea46dd9dd17c8b072d40952ffa3d8c2208aea58a", "boringssl_ssl_tests": "a1e972f0f49dcc1993cb70ee8e7d7ffeba232854", "breakpad_unittests": "2f109110a9f7dd384fa6d53ffeab368ddf1f06c0", "cacheinvalidation_unittests": "d1e211e4d2e63910ac457f809f8370e3c3de99ed", "capture_unittests": "dc05bb9dd60a79745b65fffc6af08b0c53c0e602", "cast_unittests": "b96fce0cfb03b34c8069ccf404309254883086bd", "cc_unittests": "86941b020f4feea3641acdacb2f448c468cc36da", "chrome_public_test_apk": "b405da64270ce357069a0bd45c4e511202c83a5e", "chrome_public_test_vr_apk": "921c595b721c5bcb34db8302b4b1f7fdb7ead7c6", "components_browsertests": "249682c2ddd0f7a836afc78a51d99e7a7d11a55e", "components_unittests": "3b39fc94d16e93eef3a19a5d42ded6994f2a402a", "content_browsertests": "25ad73e7e864328242caef5584ee13bdabbbc684", "content_shell_test_apk": "77040a1313cb71f31cfc4a1f3b8348158fb3f3d2", "content_unittests": "6dba0580d81134d3aff852078385a1ecbfb21149", "crypto_unittests": "79917fb2491a16ea71f4cbea50bd1b4b79d1a1e7", "device_unittests": "a3f47125b671e5184a9bc328076039d52fc06a26", "display_unittests": "52c9a2702b5e8ad1c1bf6cc41907eadb9a6052aa", "events_unittests": "990fe92479802cb76130305b513b9b6d3321bdd1", "gcm_unit_tests": "a2793bed54a6209201ce62b03071f3f1fb8d056f", "gfx_unittests": "939159119a3c414e9f4954e1cd9c28a484e08ace", "gin_unittests": "a9740cf8613663f3175dc3091be7bc6bb7136115", "gl_tests": "b31deacda208738e5839761816b999a6becb07e0", "gl_unittests": "8059ca1e5c33dc3701083862d613c020be5e0b8b", "google_apis_unittests": "8e2f1f7bf18aecbbfc80aac081c23c2724ad9eaf", "gpu_unittests": "c7c88c12de92a86770cb752e2be6481396245fa9", "ipc_tests": "3d8588e0c823ca8ad663abc07beca6a6fe60b248", "jingle_unittests": "62f7379f0448dcccc1c2c0402a266b2771e5eca5", "latency_unittests": "6ae75b591d7b33672425e40626d0bfc73481af66", "libjingle_xmpp_unittests": "3f4d0d7f43a6e23412d593900690b19e6a3a2cc5", "media_blink_unittests": "4cc952dd35068102681431b3fbca62ecf8a9b6a5", "media_service_unittests": "67c072e3a41911c779852962c18ec137ed76262a", "media_unittests": "10ed03ae898e608539d26bc91f3d10e380f053d5", "midi_unittests": "7b1172fadbb576c74d1ce12309585d2c61a2e916", "mojo_test_apk": "d075739cd4519b80d8c9c20c9cd462e25a011123", "mojo_unittests": "811dce70da275092a427ad490ef789fa56dd8df0", "net_unittests": "b488d600147ce29c7e3cf60b350a2b329b08de34", "sandbox_linux_unittests": "524e78ac45f832a0b59c794ef29db71ddd6d81c4", "services_unittests": "3f1e1585d25bef31643918e009dade1292b1cd01", "shell_dialogs_unittests": "0d1e600e9547206ec8900d5515764a381f04fa78", "skia_unittests": "a2010cf89044eccf924402568ae844439d984cd4", "sql_unittests": "01b65beeca3bef9cb914231119ca85a38a9ce6eb", "storage_unittests": "39d0d4e04e3b9e611008d7d53be9e73815631d04", "system_webview_shell_layout_test_apk": "f50a7dd93161a5db0c3eec6ab5df159f39a14a69", "ui_android_unittests": "f76e28cc0d924e1e8175f0157a1d37ecbf9bf845", "ui_base_unittests": "617265d5e8f51bfd35eeba7952a79bad796e9e81", "ui_touch_selection_unittests": "86cfd605471e2f9649dedecb77d4ba4e05a6e9fe", "unit_tests": "bcea0154442d20710ae29edede782f73a8014572", "url_unittests": "52c16e0d3f3f05a8648a719286add96e54000506", "viz_unittests": "5d163ba4a11f67f84db191a7e6886148ba5c52c1", "vr_android_unittests": "9f69fdfacc208130560ec49aa0b3a2359c2f6e5b", "vr_common_unittests": "72d7d225bd1243c9d25d2b4299e3d6150c2c9378", "vr_pixeltests": "e7ce4f24bb2bd78f2cc67ad079be06b7f89a3dee", "webview_cts_tests": "1b13bc6bbb49038f6c1eb8c97490f62a87ad8c00", "webview_instrumentation_test_apk": "298e70b24932c967f00c9bee588590be3b2d093e", "webview_ui_test_app_test_apk": "832b6ba3e18211e471e3e730576baf4e50345347", "wtf_unittests": "e7095fffa5f13932b92cbd9c0096bf2b188be415"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpLK1BMU.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpEI4Iqe', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmpOgWTOj.json', '/b/swarming/w/ir/tmp/t/tmpEI4Iqe/4455f3869b602610/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py', '--build-properties', '{"bot_id": "swarm99-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555800323689632, "id": "8915618835745360144", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Lollipop Tablet Tester/13427", "builder:Lollipop Tablet Tester", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:41254", "scheduler_invocation_id:9081048897806617888", "scheduler_job_id:chromium/Lollipop Tablet Tester", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Lollipop Tablet Tester", "buildnumber": 13427, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "got_revision_cp": "refs/heads/master@{#652776}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "parent_got_revision_cp": "refs/heads/master@{#652776}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "40365c5dcd36bff6beb9b2d3bd23f49a8afacffc", "swarm_hashes": {"android_webview_unittests": "9a856695652e57dd319e2efadd3e77d11c52ea8d", "angle_unittests": "1a6de6ee001f40eae5f1959f158102c257186b49", "base_unittests": "f052ba2ffb2e14f745e931f02008eab58bc00af7", "blink_common_unittests": "cc780758682b951b55db433cae965f406ef938a8", "blink_heap_unittests": "2bec1aaeff4a8922488ac4bf9e36152b7477e9a8", "blink_platform_unittests": "5fbea2da05fd7c85571e139e8e81beda6c853450", "blink_unittests": "fe6240746171504e35af2cd14280fa41ea08d65a", "blink_web_tests_exparchive": "5922e3086b6ab592e5f1f1dc539eeb1a6915a998", "boringssl_crypto_tests": "ea46dd9dd17c8b072d40952ffa3d8c2208aea58a", "boringssl_ssl_tests": "a1e972f0f49dcc1993cb70ee8e7d7ffeba232854", "breakpad_unittests": "2f109110a9f7dd384fa6d53ffeab368ddf1f06c0", "cacheinvalidation_unittests": "d1e211e4d2e63910ac457f809f8370e3c3de99ed", "capture_unittests": "dc05bb9dd60a79745b65fffc6af08b0c53c0e602", "cast_unittests": "b96fce0cfb03b34c8069ccf404309254883086bd", "cc_unittests": "86941b020f4feea3641acdacb2f448c468cc36da", "chrome_public_test_apk": "b405da64270ce357069a0bd45c4e511202c83a5e", "chrome_public_test_vr_apk": "921c595b721c5bcb34db8302b4b1f7fdb7ead7c6", "components_browsertests": "249682c2ddd0f7a836afc78a51d99e7a7d11a55e", "components_unittests": "3b39fc94d16e93eef3a19a5d42ded6994f2a402a", "content_browsertests": "25ad73e7e864328242caef5584ee13bdabbbc684", "content_shell_test_apk": "77040a1313cb71f31cfc4a1f3b8348158fb3f3d2", "content_unittests": "6dba0580d81134d3aff852078385a1ecbfb21149", "crypto_unittests": "79917fb2491a16ea71f4cbea50bd1b4b79d1a1e7", "device_unittests": "a3f47125b671e5184a9bc328076039d52fc06a26", "display_unittests": "52c9a2702b5e8ad1c1bf6cc41907eadb9a6052aa", "events_unittests": "990fe92479802cb76130305b513b9b6d3321bdd1", "gcm_unit_tests": "a2793bed54a6209201ce62b03071f3f1fb8d056f", "gfx_unittests": "939159119a3c414e9f4954e1cd9c28a484e08ace", "gin_unittests": "a9740cf8613663f3175dc3091be7bc6bb7136115", "gl_tests": "b31deacda208738e5839761816b999a6becb07e0", "gl_unittests": "8059ca1e5c33dc3701083862d613c020be5e0b8b", "google_apis_unittests": "8e2f1f7bf18aecbbfc80aac081c23c2724ad9eaf", "gpu_unittests": "c7c88c12de92a86770cb752e2be6481396245fa9", "ipc_tests": "3d8588e0c823ca8ad663abc07beca6a6fe60b248", "jingle_unittests": "62f7379f0448dcccc1c2c0402a266b2771e5eca5", "latency_unittests": "6ae75b591d7b33672425e40626d0bfc73481af66", "libjingle_xmpp_unittests": "3f4d0d7f43a6e23412d593900690b19e6a3a2cc5", "media_blink_unittests": "4cc952dd35068102681431b3fbca62ecf8a9b6a5", "media_service_unittests": "67c072e3a41911c779852962c18ec137ed76262a", "media_unittests": "10ed03ae898e608539d26bc91f3d10e380f053d5", "midi_unittests": "7b1172fadbb576c74d1ce12309585d2c61a2e916", "mojo_test_apk": "d075739cd4519b80d8c9c20c9cd462e25a011123", "mojo_unittests": "811dce70da275092a427ad490ef789fa56dd8df0", "net_unittests": "b488d600147ce29c7e3cf60b350a2b329b08de34", "sandbox_linux_unittests": "524e78ac45f832a0b59c794ef29db71ddd6d81c4", "services_unittests": "3f1e1585d25bef31643918e009dade1292b1cd01", "shell_dialogs_unittests": "0d1e600e9547206ec8900d5515764a381f04fa78", "skia_unittests": "a2010cf89044eccf924402568ae844439d984cd4", "sql_unittests": "01b65beeca3bef9cb914231119ca85a38a9ce6eb", "storage_unittests": "39d0d4e04e3b9e611008d7d53be9e73815631d04", "system_webview_shell_layout_test_apk": "f50a7dd93161a5db0c3eec6ab5df159f39a14a69", "ui_android_unittests": "f76e28cc0d924e1e8175f0157a1d37ecbf9bf845", "ui_base_unittests": "617265d5e8f51bfd35eeba7952a79bad796e9e81", "ui_touch_selection_unittests": "86cfd605471e2f9649dedecb77d4ba4e05a6e9fe", "unit_tests": "bcea0154442d20710ae29edede782f73a8014572", "url_unittests": "52c16e0d3f3f05a8648a719286add96e54000506", "viz_unittests": "5d163ba4a11f67f84db191a7e6886148ba5c52c1", "vr_android_unittests": "9f69fdfacc208130560ec49aa0b3a2359c2f6e5b", "vr_common_unittests": "72d7d225bd1243c9d25d2b4299e3d6150c2c9378", "vr_pixeltests": "e7ce4f24bb2bd78f2cc67ad079be06b7f89a3dee", "webview_cts_tests": "1b13bc6bbb49038f6c1eb8c97490f62a87ad8c00", "webview_instrumentation_test_apk": "298e70b24932c967f00c9bee588590be3b2d093e", "webview_ui_test_app_test_apk": "832b6ba3e18211e471e3e730576baf4e50345347", "wtf_unittests": "e7095fffa5f13932b92cbd9c0096bf2b188be415"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpLK1BMU.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpEI4Iqe', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmpOgWTOj.json', '/b/swarming/w/ir/tmp/t/tmpEI4Iqe/4455f3869b602610/output.json'] returned exit code 0