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/tmphZzIgv.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpEXGqGN --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/tmpIj24ERmerge_script_log --merge-additional-args '["--bucket", "chromium-result-details", "--test-name", "cacheinvalidation_unittests"]' --build-properties '{"bot_id": "swarm96-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553458773474746, "id": "8918074129104160064", "project": "chromium", "tags": ["build_address:luci.chromium.ci/KitKat Phone Tester (dbg)/12595", "builder:KitKat Phone Tester (dbg)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/df4289eaea2d4b063d3076eca0eba4e3212e0505", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:40678", "scheduler_invocation_id:9083504191217821536", "scheduler_job_id:chromium/KitKat Phone Tester (dbg)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "KitKat Phone Tester (dbg)", "buildnumber": 12595, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "got_revision_cp": "refs/heads/master@{#643734}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "parent_got_revision_cp": "refs/heads/master@{#643734}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "swarm_hashes": {"android_webview_unittests": "6af6a6f75f5c03f5e129008662b68809d2d3392e", "angle_unittests": "e7efb4707bf26013053b327c04118843a732f8ac", "base_unittests": "fd839d7f53df410527455e907c1efd79750f1d90", "blink_common_unittests": "e261912aea9eb2807d4bde1a233a33f54b1c7ee2", "blink_heap_unittests": "bb1c5bd1e759899695cd96da5ac1cdaf9dceb4c6", "blink_platform_unittests": "f3294564ba6e09d218b4448844031442ef4b7ce4", "blink_unittests": "d6bb1251dfe57861b989221a4d2c296bd0502eed", "blink_web_tests_exparchive": "d24ebd06e1e2ebe75938aea56a644af20f77bfd3", "boringssl_crypto_tests": "e610f52557dd9c9359226e1b8f35dfba02c8a9cf", "boringssl_ssl_tests": "11dcc6fe11e60d84ed98c7d0393f4946aa1135dd", "breakpad_unittests": "9ed215e237069e2af7a9fb7924e4891798ab9891", "cacheinvalidation_unittests": "39326f18e2fc58d6ff7f231440ba89ed6933fc56", "capture_unittests": "53347a669cbcc189381a6a68eb5a836d522918c7", "cast_unittests": "04506375dd5cd8bb497b8ee39949daa9258545bb", "cc_unittests": "80bb7b5d090f24d326360e4e0ac07e6caea3a27e", "chrome_public_test_apk": "21cb43e818c76ff8e0136f8c335b9daeb810a964", "chrome_public_test_vr_apk": "4a7ec2edfe1aa4d41b1de3e8c901c5b779ec4f09", "components_browsertests": "b3d597df9dea7ec26e3fc0c194c5add0850c80b3", "components_unittests": "2b8dd2251b7ee23fe4e90ed24e0b50c6922f9099", "content_browsertests": "a3e11a4efa4d3f4858e8e569977bd72ce4ab8292", "content_shell_test_apk": "5f413df7c148fc1d9edb24c70a7d627cae69deeb", "content_unittests": "079c18bfd666d0f992dda0118b99fc8ca81fa190", "crypto_unittests": "fb215959e791c80bf0a129c014f8a2b785731cc0", "device_unittests": "9fed47a69ac27290353154c8832ea2a76c5ef8be", "display_unittests": "6384452d164ea1495515225d11808aeab391aa5c", "events_unittests": "668ddbc2836a82cac5d9eaae397df5f6b33b7879", "gcm_unit_tests": "b49a09cb59d7bfeb6ba0e3b0c987edb3c3688d8f", "gfx_unittests": "bd1eaf76bd8c1768be9acb471746ab27c1ee2e75", "gin_unittests": "22cf6b8d5296ea06669231fb3615882e49dc90b0", "gl_tests": "0ebbaccc5298b07253a0931798568d23a3859d56", "gl_unittests": "7111c8b5b7d572ee626ec9b573dabff69b42b972", "google_apis_unittests": "304b1ff801a741f4b0dacc59c27e6091a0f0c8e7", "gpu_unittests": "4c4db615ca664a5b4da15b27a5cc68c086a51c97", "ipc_tests": "da925b70a469d8abed331a6ea58001110f5d5024", "jingle_unittests": "bf443306a821e405c65677eed075507dfac48267", "latency_unittests": "31cf451aa44e410b40652e2dd305ff156969bf85", "libjingle_xmpp_unittests": "09ad97caad60b8bff22f1ecad61bc90e71cbc2ee", "media_blink_unittests": "325ba3d03495dd68bb3512ab7881b70f4400b224", "media_service_unittests": "59775ba6b921e7247bde77c0eb9aa6ee1afef5ad", "media_unittests": "60da53915af74a9627134de49cda4f2a340a6216", "midi_unittests": "33b932da453c467175e9dc624afaf8af96316724", "mojo_test_apk": "874fc4649f6a8c30b8ad69fb357bc0c161082228", "mojo_unittests": "938f03f812a8766c483e90dc8178a5da7686ea46", "net_unittests": "ddaf1a18b6ffe608ea1d641c4537e5af1a29d951", "sandbox_linux_unittests": "2008bfd31568136e1c4300245b4c8523fca591f3", "services_unittests": "fb19ba2729306469977504cc03358038192822a0", "shell_dialogs_unittests": "ab267e95a1c9bae06fe6df277abc74c39736aa28", "skia_unittests": "710e85ebc7310ce3c822449c19329e8a4afcb372", "sql_unittests": "6b5e5879dd86debc2abc26906d08b8593cbb0778", "storage_unittests": "a8d61f20d54e79d2c19f4358484394cc1ab51d1a", "ui_android_unittests": "8770bb930b654f54acc4c179c3be6cbc354eea00", "ui_base_unittests": "7d56a4f685e4ebf6bc0b4496713bfdc574aaa2df", "ui_touch_selection_unittests": "1c3304e77ce712a670512612cf5b14d40c83480e", "unit_tests": "4fae2743a34d5f87513fd399a82f5b49ac6ca2c3", "url_unittests": "4aec20ba11887695a2274def456318ea654c58d1", "viz_unittests": "6f942d64e003b8e33a2f9ce2ce94e061e0cba4d1", "vr_android_unittests": "81473302290011955a630c10f6c9b637e4188e48", "vr_common_unittests": "31c3b3c6e7f6ec184bcc08f7aff0cf082933c46a", "vr_pixeltests": "a62ff6a6b6bd33efc5e383fb95af843b7f73ff8b", "webview_cts_tests": "5ab5f62605c908b55d4bf0a8a7a80b4e3da8b349", "webview_instrumentation_test_apk": "6c6628e7b523d6537116b62673604435a4a8c106", "wtf_unittests": "ac51da88ad8e912387a8927548b97443750171c9"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmprLD7Q7.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/tmp0NX3AD.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/tmphZzIgv.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpEXGqGN', '--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/tmpIj24ERmerge_script_log', '--merge-additional-args', '["--bucket", "chromium-result-details", "--test-name", "cacheinvalidation_unittests"]', '--build-properties', '{"bot_id": "swarm96-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553458773474746, "id": "8918074129104160064", "project": "chromium", "tags": ["build_address:luci.chromium.ci/KitKat Phone Tester (dbg)/12595", "builder:KitKat Phone Tester (dbg)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/df4289eaea2d4b063d3076eca0eba4e3212e0505", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:40678", "scheduler_invocation_id:9083504191217821536", "scheduler_job_id:chromium/KitKat Phone Tester (dbg)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "KitKat Phone Tester (dbg)", "buildnumber": 12595, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "got_revision_cp": "refs/heads/master@{#643734}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "parent_got_revision_cp": "refs/heads/master@{#643734}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "swarm_hashes": {"android_webview_unittests": "6af6a6f75f5c03f5e129008662b68809d2d3392e", "angle_unittests": "e7efb4707bf26013053b327c04118843a732f8ac", "base_unittests": "fd839d7f53df410527455e907c1efd79750f1d90", "blink_common_unittests": "e261912aea9eb2807d4bde1a233a33f54b1c7ee2", "blink_heap_unittests": "bb1c5bd1e759899695cd96da5ac1cdaf9dceb4c6", "blink_platform_unittests": "f3294564ba6e09d218b4448844031442ef4b7ce4", "blink_unittests": "d6bb1251dfe57861b989221a4d2c296bd0502eed", "blink_web_tests_exparchive": "d24ebd06e1e2ebe75938aea56a644af20f77bfd3", "boringssl_crypto_tests": "e610f52557dd9c9359226e1b8f35dfba02c8a9cf", "boringssl_ssl_tests": "11dcc6fe11e60d84ed98c7d0393f4946aa1135dd", "breakpad_unittests": "9ed215e237069e2af7a9fb7924e4891798ab9891", "cacheinvalidation_unittests": "39326f18e2fc58d6ff7f231440ba89ed6933fc56", "capture_unittests": "53347a669cbcc189381a6a68eb5a836d522918c7", "cast_unittests": "04506375dd5cd8bb497b8ee39949daa9258545bb", "cc_unittests": "80bb7b5d090f24d326360e4e0ac07e6caea3a27e", "chrome_public_test_apk": "21cb43e818c76ff8e0136f8c335b9daeb810a964", "chrome_public_test_vr_apk": "4a7ec2edfe1aa4d41b1de3e8c901c5b779ec4f09", "components_browsertests": "b3d597df9dea7ec26e3fc0c194c5add0850c80b3", "components_unittests": "2b8dd2251b7ee23fe4e90ed24e0b50c6922f9099", "content_browsertests": "a3e11a4efa4d3f4858e8e569977bd72ce4ab8292", "content_shell_test_apk": "5f413df7c148fc1d9edb24c70a7d627cae69deeb", "content_unittests": "079c18bfd666d0f992dda0118b99fc8ca81fa190", "crypto_unittests": "fb215959e791c80bf0a129c014f8a2b785731cc0", "device_unittests": "9fed47a69ac27290353154c8832ea2a76c5ef8be", "display_unittests": "6384452d164ea1495515225d11808aeab391aa5c", "events_unittests": "668ddbc2836a82cac5d9eaae397df5f6b33b7879", "gcm_unit_tests": "b49a09cb59d7bfeb6ba0e3b0c987edb3c3688d8f", "gfx_unittests": "bd1eaf76bd8c1768be9acb471746ab27c1ee2e75", "gin_unittests": "22cf6b8d5296ea06669231fb3615882e49dc90b0", "gl_tests": "0ebbaccc5298b07253a0931798568d23a3859d56", "gl_unittests": "7111c8b5b7d572ee626ec9b573dabff69b42b972", "google_apis_unittests": "304b1ff801a741f4b0dacc59c27e6091a0f0c8e7", "gpu_unittests": "4c4db615ca664a5b4da15b27a5cc68c086a51c97", "ipc_tests": "da925b70a469d8abed331a6ea58001110f5d5024", "jingle_unittests": "bf443306a821e405c65677eed075507dfac48267", "latency_unittests": "31cf451aa44e410b40652e2dd305ff156969bf85", "libjingle_xmpp_unittests": "09ad97caad60b8bff22f1ecad61bc90e71cbc2ee", "media_blink_unittests": "325ba3d03495dd68bb3512ab7881b70f4400b224", "media_service_unittests": "59775ba6b921e7247bde77c0eb9aa6ee1afef5ad", "media_unittests": "60da53915af74a9627134de49cda4f2a340a6216", "midi_unittests": "33b932da453c467175e9dc624afaf8af96316724", "mojo_test_apk": "874fc4649f6a8c30b8ad69fb357bc0c161082228", "mojo_unittests": "938f03f812a8766c483e90dc8178a5da7686ea46", "net_unittests": "ddaf1a18b6ffe608ea1d641c4537e5af1a29d951", "sandbox_linux_unittests": "2008bfd31568136e1c4300245b4c8523fca591f3", "services_unittests": "fb19ba2729306469977504cc03358038192822a0", "shell_dialogs_unittests": "ab267e95a1c9bae06fe6df277abc74c39736aa28", "skia_unittests": "710e85ebc7310ce3c822449c19329e8a4afcb372", "sql_unittests": "6b5e5879dd86debc2abc26906d08b8593cbb0778", "storage_unittests": "a8d61f20d54e79d2c19f4358484394cc1ab51d1a", "ui_android_unittests": "8770bb930b654f54acc4c179c3be6cbc354eea00", "ui_base_unittests": "7d56a4f685e4ebf6bc0b4496713bfdc574aaa2df", "ui_touch_selection_unittests": "1c3304e77ce712a670512612cf5b14d40c83480e", "unit_tests": "4fae2743a34d5f87513fd399a82f5b49ac6ca2c3", "url_unittests": "4aec20ba11887695a2274def456318ea654c58d1", "viz_unittests": "6f942d64e003b8e33a2f9ce2ce94e061e0cba4d1", "vr_android_unittests": "81473302290011955a630c10f6c9b637e4188e48", "vr_common_unittests": "31c3b3c6e7f6ec184bcc08f7aff0cf082933c46a", "vr_pixeltests": "a62ff6a6b6bd33efc5e383fb95af843b7f73ff8b", "webview_cts_tests": "5ab5f62605c908b55d4bf0a8a7a80b4e3da8b349", "webview_instrumentation_test_apk": "6c6628e7b523d6537116b62673604435a4a8c106", "wtf_unittests": "ac51da88ad8e912387a8927548b97443750171c9"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmprLD7Q7.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/tmp0NX3AD.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 5',) ok_ret: ALL_OK step_test_data: <lambda>(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 45217 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/8918074129104160064 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itrplL7x/luci_context.694658529 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: swarm96-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43ca2d48fdd30111 TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TERM: linux TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t UPSTART_EVENTS: net-device-up UPSTART_INSTANCE: UPSTART_JOB: chromebuild-startup USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-03-24 13:23:48,215 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpEXGqGN' 2019-03-24 13:23:48,215 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpEXGqGN' already exists! 2019-03-24 13:23:48,215 - root: [WARNING] task_output_dir existing content: [] 2019-03-24 13:23:48,215 - 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/tmp0NX3AD.json -output-dir /b/swarming/w/ir/tmp/t/tmpEXGqGN -task-summary-json /b/swarming/w/ir/tmp/t/tmprLD7Q7.json [D2019-03-24T13:23:48.221428-07:00 7207 0 auth.go:1265] Minting a new token {"key":"luci_ctx/f538a391fb38c8cd86efee39d47b0c49566f5f895a687088928be7bf736e2a19", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-24T13:23:48.221504-07:00 7207 0 luci_ctx.go:138] POST http://127.0.0.1:37885/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/f538a391fb38c8cd86efee39d47b0c49566f5f895a687088928be7bf736e2a19", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-24T13:23:48.223100-07:00 7207 0 auth.go:1222] Token expires in 13m37.776929867s {"key":"luci_ctx/f538a391fb38c8cd86efee39d47b0c49566f5f895a687088928be7bf736e2a19", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43ca2e7c018a1410: exit 0 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/9ede37/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/iokE4f_I/output.json I 0.000s Main command: ../../build/android/test_runner.py gtest --suite cacheinvalidation_unittests --output-directory . --runtime-deps-path gen.runtime/third_party/cacheinvalidation/cacheinvalidation_unittests__test_runner_script.runtime_deps -v --store-tombstones --gs-results-bucket=chromium-result-details --recover-devices --test-launcher-summary-output=/b/swarming/w/iokE4f_I/output.json I 0.006s Main condition '<lambda>' met I 0.008s Main condition '<lambda>' met I 3.138s TimeoutThread-1-for-prepare_device(07db034a0075fb61) condition 'sd_card_ready' met (0.0s) I 3.691s TimeoutThread-1-for-prepare_device(07db034a0075fb61) condition 'pm_ready' met (0.6s) I 3.712s TimeoutThread-1-for-prepare_device(07db034a0075fb61) condition 'boot_completed' met (0.6s) I 7.565s calculate_device_checksums condition '<lambda>' met (0.1s) I 9.031s list_tests(07db034a0075fb61) flags: I 9.032s list_tests(07db034a0075fb61) --gtest_list_tests I 10.473s list_tests(07db034a0075fb61) /storage/emulated/legacy/temp_file-67e88902174e6.gtest_out size on device: 682 I 10.547s Main Using external sharding settings. This is shard 0/1 I 10.547s Main STARTING TRY #1/3 I 10.547s Main Will run 28 tests on 1 devices: 07db034a0075fb61 W 10.615s run_tests_on_device(07db034a0075fb61) No tombstones to clear. I 12.521s run_tests_on_device(07db034a0075fb61) flags: I 12.522s run_tests_on_device(07db034a0075fb61) Getting logdog client. I 14.044s run_tests_on_device(07db034a0075fb61) /storage/emulated/legacy/temp_file-7082c86e669c7.gtest_out size on device: 95753 I 14.158s run_tests_on_device(07db034a0075fb61) Logcat saved to https://luci-logdog.appspot.com/v/?s=chromium%2Fandroid%2Fswarming%2Flogcats%2F43c77ce6b1cce311%2F%2B%2Flogcat_logcat_-2631999291401687399_20190324T074803-UTC_07db034a0075fb61 I 14.160s archive Writing text to logdog stream, logcat_logcat_-2631999291401687399_20190324T074803-UTC_07db034a0075fb61 I 14.767s run_tests_on_device(07db034a0075fb61) >>ScopedMainEntryLogger I 14.767s run_tests_on_device(07db034a0075fb61) 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 14.767s run_tests_on_device(07db034a0075fb61) [==========] Running 28 tests from 4 test suites. I 14.767s run_tests_on_device(07db034a0075fb61) [----------] Global test environment set-up. I 14.767s run_tests_on_device(07db034a0075fb61) [----------] 10 tests from InvalidationClientImplTest I 14.767s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.Start I 14.767s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 16384) Enqueuing 0xc926000 with delay 181 I 14.767s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1971898983) Enqueuing 0xc926000 with delay 181 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154168) Running task 0xc926000 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154168) Running task 0xc926000 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154168) Running task 0xc926000 I 14.768s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154168) Running task 0xc926000 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979013376 with a delay 1074646029, Now = 0 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154168) Running task 0xc926000 I 14.768s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5805458614272596434" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979013764 with a delay -1093964128, Now = 500000 I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013376 with a delay -2147483632, Now = 60000000 I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154168) Running task 0xc9a0120 I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.769s run_tests_on_device(07db034a0075fb61) [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: "-5805458614272596434" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5805458614272596434" 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 14.769s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5805458614272596434" I 14.769s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979013692 with a delay -1093964184, Now = 1200000000 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979013664 with a delay -1093964184, Now = 0 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.770s run_tests_on_device(07db034a0075fb61) [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 14.770s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013664 with a delay 0, Now = 10000000 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.770s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.770s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.Start (10 ms) I 14.771s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.GenerateNonce I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 24576) Enqueuing 0xc926000 with delay 181 I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.771s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.GenerateNonce (1 ms) I 14.771s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.Register I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 18432) Enqueuing 0xc926000 with delay 181 I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972742921) Enqueuing 0xc926000 with delay 181 I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.771s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.771s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1900153976 with a delay 1074646029, Now = 0 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5806140198305140851" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1900154188 with a delay -1093964392, Now = 500000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1900153976 with a delay -2147483632, Now = 60000000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc9a0120 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.772s run_tests_on_device(07db034a0075fb61) [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: "-5806140198305140851" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5806140198305140851" 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 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5806140198305140851" I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1978999804 with a delay -1093964448, Now = 1200000000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1978999776 with a delay -1093964448, Now = 0 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [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 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1978999776 with a delay 0, Now = 10000000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074658923) Enqueuing 0xc9ac470 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc9ac470 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1900154188 with a delay 1074658923, Now = 500000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1900154144 with a delay 3, Now = 60000000 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xca26590 I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.772s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.773s run_tests_on_device(07db034a0075fb61) [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 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1979019984) Enqueuing 0xca26590 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 14.773s run_tests_on_device(07db034a0075fb61) [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 14.773s run_tests_on_device(07db034a0075fb61) [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 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.773s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.Register (13 ms) I 14.773s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.Invalidations I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 24576) Enqueuing 0xc926000 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972742921) Enqueuing 0xc926000 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.773s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979013536 with a delay 1074646029, Now = 0 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2527089254527028304" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979013924 with a delay -1093964424, Now = 500000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013536 with a delay -2147483632, Now = 60000000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc9a0120 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.773s run_tests_on_device(07db034a0075fb61) [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: "-2527089254527028304" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2527089254527028304" 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 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2527089254527028304" I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979013852 with a delay -1093964480, Now = 1200000000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979013824 with a delay -1093964480, Now = 0 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [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 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013824 with a delay 0, Now = 10000000 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.773s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 2054904246) Enqueuing 0xc9ac470 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.774s run_tests_on_device(07db034a0075fb61) [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 14.774s run_tests_on_device(07db034a0075fb61) [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 14.774s run_tests_on_device(07db034a0075fb61) [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 14.774s run_tests_on_device(07db034a0075fb61) [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 14.774s run_tests_on_device(07db034a0075fb61) [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 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 32768) Enqueuing 0xc9b87c0 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 32768) Enqueuing 0xc9b87c0 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 32768) Enqueuing 0xc9b87c0 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc9b87c0 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1979013924 with a delay 296960, Now = 500000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9b87c0 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc9b87c0 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc9b87c0 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xca328e0 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.774s run_tests_on_device(07db034a0075fb61) [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 14.774s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.Invalidations (13 ms) I 14.774s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.ServerRequests I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 24576) Enqueuing 0xc926000 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963456) Enqueuing 0xc926000 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.774s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979013536 with a delay 1074646029, Now = 0 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc926000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3020683500147030157" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979013924 with a delay -1093964280, Now = 500000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013536 with a delay -2147483632, Now = 60000000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1900154640) Running task 0xc9a0120 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.774s run_tests_on_device(07db034a0075fb61) [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: "-3020683500147030157" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3020683500147030157" 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 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3020683500147030157" I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979013852 with a delay -1093964336, Now = 1200000000 I 14.774s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979013824 with a delay -1093964336, Now = 0 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [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 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013824 with a delay 0, Now = 10000000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963606) Enqueuing 0xc9ac470 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.775s run_tests_on_device(07db034a0075fb61) [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 14.775s run_tests_on_device(07db034a0075fb61) [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 14.775s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(294)] Adding subtree: { } I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 1979013924 with a delay -1093964304, Now = 500000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 14.775s run_tests_on_device(07db034a0075fb61) [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 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.775s run_tests_on_device(07db034a0075fb61) [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 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.775s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.ServerRequests (12 ms) I 14.775s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 75501568) Enqueuing 0xc926000 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972742921) Enqueuing 0xc926000 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.775s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979017704 with a delay 1074646029, Now = 0 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7276275374705622791" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979018092 with a delay -1093964240, Now = 500000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017704 with a delay -2147483632, Now = 60000000 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc9a0120 I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.775s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.776s run_tests_on_device(07db034a0075fb61) [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: "7276275374705622791" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7276275374705622791" 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 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7276275374705622791" I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979018020 with a delay -1093964296, Now = 1200000000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979017992 with a delay -1093964296, Now = 0 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [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 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017992 with a delay 0, Now = 10000000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913479) Enqueuing 0xc9ac470 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.776s run_tests_on_device(07db034a0075fb61) [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 14.776s run_tests_on_device(07db034a0075fb61) [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 14.776s run_tests_on_device(07db034a0075fb61) [ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.776s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.IncomingErrorMessage (10 ms) I 14.776s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc926000 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972742921) Enqueuing 0xc926000 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.776s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979013568 with a delay 1074646029, Now = 0 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "6621823233822603096" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979013956 with a delay -1093964368, Now = 500000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013568 with a delay -2147483632, Now = 60000000 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc9a0120 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.776s run_tests_on_device(07db034a0075fb61) [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: "6621823233822603096" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.776s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "6621823233822603096" 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 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "6621823233822603096" I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979013884 with a delay -1093964424, Now = 1200000000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979013856 with a delay -1093964424, Now = 0 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [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 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013856 with a delay 0, Now = 10000000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc9ac470 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1979013956 with a delay 1074658923, Now = 500000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1979013736 with a delay 1, Now = 60000000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xca26590 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.777s run_tests_on_device(07db034a0075fb61) [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 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913479) Enqueuing 0xca26590 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 14.777s run_tests_on_device(07db034a0075fb61) [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 14.777s run_tests_on_device(07db034a0075fb61) [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 14.777s run_tests_on_device(07db034a0075fb61) [ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message I 14.777s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.777s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (12 ms) I 14.777s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.NetworkTimeouts I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 75501568) Enqueuing 0xc926000 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963456) Enqueuing 0xc926000 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.777s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979017704 with a delay 1074646029, Now = 0 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.777s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7995921311930398374" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979018092 with a delay -1093964280, Now = 500000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017704 with a delay -2147483632, Now = 60000000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc9a0120 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.778s run_tests_on_device(07db034a0075fb61) [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: "7995921311930398374" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7995921311930398374" 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 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7995921311930398374" I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979018020 with a delay -1093964336, Now = 1200000000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979017992 with a delay -1093964336, Now = 0 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [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 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017992 with a delay 0, Now = 10000000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc9ac470 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1979018092 with a delay 1074658923, Now = 500000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1979017872 with a delay 1, Now = 60000000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9ac470 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xca26590 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.778s run_tests_on_device(07db034a0075fb61) [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 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xd3297a0 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0x1025e700 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0x102e4b70 I 14.778s run_tests_on_device(07db034a0075fb61) [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 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true I 14.778s run_tests_on_device(07db034a0075fb61) [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 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1979018092 with a delay -1093964320, Now = 500000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x102e4b70 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017872 with a delay 0, Now = 60000000 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x102e4b70 with delay 181 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0x1035ec90 I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.778s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.778s run_tests_on_device(07db034a0075fb61) [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 14.778s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.NetworkTimeouts (13 ms) I 14.779s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc926000 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963464) Enqueuing 0xc926000 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.779s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979013568 with a delay 1074646029, Now = 0 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc926000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2147985617772287164" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979013956 with a delay -1093964288, Now = 500000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013568 with a delay -2147483632, Now = 60000000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1970466456) Running task 0xc9a0120 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.779s run_tests_on_device(07db034a0075fb61) [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: "2147985617772287164" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2147985617772287164" 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 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2147985617772287164" I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979013884 with a delay -1093964344, Now = 1200000000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979013856 with a delay -1093964344, Now = 0 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [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 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979013856 with a delay 0, Now = 10000000 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1979005064) Enqueuing 0xc9ac470 with delay 181 I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.779s run_tests_on_device(07db034a0075fb61) [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 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.779s run_tests_on_device(07db034a0075fb61) [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 14.779s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.NoRegistrationSummary (10 ms) I 14.779s run_tests_on_device(07db034a0075fb61) [ RUN ] InvalidationClientImplTest.Heartbeats I 14.779s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 75501568) Enqueuing 0xc926000 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963424) Enqueuing 0xc926000 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972169763) Enqueuing 0xc926000 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.780s run_tests_on_device(07db034a0075fb61) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979017584 with a delay 1074646029, Now = 0 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc926000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3265008969488404332" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1979017972 with a delay -1093964248, Now = 500000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017584 with a delay -2147483632, Now = 60000000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012896) Running task 0xc9a0120 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.780s run_tests_on_device(07db034a0075fb61) [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: "3265008969488404332" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972913711) Enqueuing 0xc9a0120 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3265008969488404332" 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 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3265008969488404332" I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1979017900 with a delay -1093964304, Now = 1200000000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1979017872 with a delay -1093964304, Now = 0 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [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 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972238467) Enqueuing 0xc9a0120 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017872 with a delay 0, Now = 10000000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc9a0120 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1962990412) Running task 0xd3297a0 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1962990412) Running task 0x1025e700 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1962990412) Running task 0x54208d20 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 14.780s run_tests_on_device(07db034a0075fb61) [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 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1979017972 with a delay -1093964320, Now = 500000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x54208d20 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979017900 with a delay 12, Now = 1200000000 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x54208d20 with delay 181 I 14.780s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1962990412) Running task 0x54282e40 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [ OK ] InvalidationClientImplTest.Heartbeats (19 ms) I 14.781s run_tests_on_device(07db034a0075fb61) [----------] 10 tests from InvalidationClientImplTest (114 ms total) I 14.781s run_tests_on_device(07db034a0075fb61) I 14.781s run_tests_on_device(07db034a0075fb61) [----------] 13 tests from ProtocolHandlerTest I 14.781s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.SendInitializeOnly I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1974567992) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc926000 I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1979004796 with a delay -1093964216, Now = 500000 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc9a0120 I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.SendInitializeOnly (3 ms) I 14.781s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) I 14.781s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1971845833) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1971845833) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1979018232) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1979018400) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1979018840) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc926000 I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1979015348 with a delay -1093964648, Now = 500000 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc926000 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc926000 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc926000 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc926000 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc926000 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1972742921) Running task 0xc9a0120 I 14.781s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms) I 14.781s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) I 14.781s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms) I 14.781s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [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 14.781s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) I 14.781s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch I 14.781s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.MinorVersionMismatch (1 ms) I 14.782s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.ConfigMessage I 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1979017336) Enqueuing 0xc926000 with delay 181 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1971864547) Running task 0xc926000 I 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1979015348 with a delay -1093964032, Now = 500000 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1971864547) Running task 0xc9a0120 I 14.782s run_tests_on_device(07db034a0075fb61) [WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 I 14.782s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.ConfigMessage (12 ms) I 14.782s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.ErrorMessage I 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) I 14.782s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.TokenMismatch I 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) I 14.782s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.TokenMissing I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1972267743) Enqueuing 0xc926000 with delay 181 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1971864547) Running task 0xc926000 I 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1979015348 with a delay -1093963864, Now = 500000 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1971864547) Running task 0xc9a0120 I 14.782s run_tests_on_device(07db034a0075fb61) [WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } I 14.782s run_tests_on_device(07db034a0075fb61) [WARNING:protocol-handler.cc(313)] Unable to build message I 14.782s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) I 14.782s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1979016512) Enqueuing 0xc926000 with delay 181 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1971864547) Running task 0xc926000 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1979015348 with a delay 4096, Now = 500000 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xc926000 with delay 181 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1971864547) Running task 0xc9a0120 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [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 14.782s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (3 ms) I 14.782s run_tests_on_device(07db034a0075fb61) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:protocol-handler.cc(139)] Incoming message: { } I 14.782s run_tests_on_device(07db034a0075fb61) [ERROR:ticl-message-validator.cc(361)] required field header missing from { } I 14.782s run_tests_on_device(07db034a0075fb61) [ERROR:protocol-handler.cc(145)] Received invalid message: { } I 14.782s run_tests_on_device(07db034a0075fb61) [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (2 ms) I 14.782s run_tests_on_device(07db034a0075fb61) [----------] 13 tests from ProtocolHandlerTest (36 ms total) I 14.782s run_tests_on_device(07db034a0075fb61) I 14.782s run_tests_on_device(07db034a0075fb61) [----------] 3 tests from RecurringTaskTest I 14.782s run_tests_on_device(07db034a0075fb61) [ RUN ] RecurringTaskTest.PeriodicTask I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1979012840 with a delay 1972733463, Now = 10000 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x0 with delay 0 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x2710 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979012992) Task running: 10000 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012840 with a delay 1974545092, Now = 60000 I 14.782s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x2710 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x11170 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979012904) Task running: 70000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012840 with a delay 1974545092, Now = 60000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x11170 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x1fbd0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013024) Task running: 130000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012840 with a delay 1974545092, Now = 60000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x1fbd0 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x2e630 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013064) Task running: 190000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012840 with a delay 1974545092, Now = 60000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x2e630 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x3d090 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013024) Task running: 250000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012840 with a delay 1974545092, Now = 60000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3d090 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x4baf0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013064) Task running: 310000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012840 with a delay 1974545092, Now = 60000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x4baf0 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x5a550 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013024) Task running: 370000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012840 with a delay 1974545092, Now = 60000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x5a550 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012864) Running task 0x68fb0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013064) Task running: 430000 I 14.783s run_tests_on_device(07db034a0075fb61) [ OK ] RecurringTaskTest.PeriodicTask (6 ms) I 14.783s run_tests_on_device(07db034a0075fb61) [ RUN ] RecurringTaskTest.ExponentialBackoffTask I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1979012872 with a delay 1979012656, Now = 10000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x0 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0x2710 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013080) Task running: 10000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012872 with a delay 1974545092, Now = 50000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x2710 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0xea60 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013136) Task running: 60000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012872 with a delay 1974545092, Now = 149000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xea60 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0x33450 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013080) Task running: 210000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012872 with a delay 1974545092, Now = 248000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x33450 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0x704e0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013248) Task running: 460000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012872 with a delay 1974545092, Now = 446000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x704e0 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0xde2b0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013304) Task running: 910000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012872 with a delay 1974545092, Now = 842000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xde2b0 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0x1adb00 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013360) Task running: 1760000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012872 with a delay 1974545092, Now = 1040000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x1adb00 with delay 0 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0x2ab980 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013416) Task running: 2800000 I 14.783s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1979012872 with a delay 1974545092, Now = 1040000 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x2ab980 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012952) Running task 0x3a9800 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979013472) Task running: 3840000 I 14.784s run_tests_on_device(07db034a0075fb61) [ OK ] RecurringTaskTest.ExponentialBackoffTask (6 ms) I 14.784s run_tests_on_device(07db034a0075fb61) [ RUN ] RecurringTaskTest.OneShotTask I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1979012840 with a delay 10, Now = 10000 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x0 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012888) Running task 0x2710 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979012960) Task running: 10000 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1979012840 with a delay 0, Now = 10000 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x2710 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 1979012960) Running task 0x4e20 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:recurring-task_test.cc(71)] (1979012864) Task running: 20000 I 14.784s run_tests_on_device(07db034a0075fb61) [ OK ] RecurringTaskTest.OneShotTask (2 ms) I 14.784s run_tests_on_device(07db034a0075fb61) [----------] 3 tests from RecurringTaskTest (14 ms total) I 14.784s run_tests_on_device(07db034a0075fb61) I 14.784s run_tests_on_device(07db034a0075fb61) [----------] 2 tests from ThrottleTest I 14.784s run_tests_on_device(07db034a0075fb61) [ RUN ] ThrottleTest.ThrottlingScripted I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 2) Enqueuing 0x13880 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xe4e1c0 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700 I 14.784s run_tests_on_device(07db034a0075fb61) [ OK ] ThrottleTest.ThrottlingScripted (2 ms) I 14.784s run_tests_on_device(07db034a0075fb61) [ RUN ] ThrottleTest.ThrottlingStorm I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 2) Enqueuing 0x2710 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xf4240 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x1e8480 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x1e8480 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x2dc6c0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x2dc6c0 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d0900 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3d0900 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x4c4b40 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x4c4b40 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x5b8d80 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963552) Enqueuing 0x5b8d80 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3938700 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3a2c940 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3a2c940 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3b20b80 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3b20b80 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3c14dc0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3c14dc0 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d09000 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3d09000 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3dfd240 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x3dfd240 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3ef1480 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963552) Enqueuing 0x3ef1480 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7270e00 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x7270e00 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7365040 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x7365040 with delay 0 I 14.784s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7459280 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x7459280 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x754d4c0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x754d4c0 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7641700 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x7641700 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7735940 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0x7735940 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7829b80 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963552) Enqueuing 0x7829b80 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaba9500 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xaba9500 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xac9d740 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xac9d740 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xad91980 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xad91980 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xae85bc0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xae85bc0 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaf79e00 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xaf79e00 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb06e040 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xb06e040 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb162280 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963552) Enqueuing 0xb162280 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe4e1c00 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xe4e1c00 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe5d5e40 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xe5d5e40 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe6ca080 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xe6ca080 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe7be2c0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xe7be2c0 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe8b2500 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xe8b2500 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe9a6740 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: 1074659927) Enqueuing 0xe9a6740 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xea9a980 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(33)] (Now: -1093963552) Enqueuing 0xea9a980 with delay 0 I 14.785s run_tests_on_device(07db034a0075fb61) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x11e1a300 I 14.785s run_tests_on_device(07db034a0075fb61) [ OK ] ThrottleTest.ThrottlingStorm (14 ms) I 14.785s run_tests_on_device(07db034a0075fb61) [----------] 2 tests from ThrottleTest (16 ms total) I 14.785s run_tests_on_device(07db034a0075fb61) I 14.785s run_tests_on_device(07db034a0075fb61) [----------] Global test environment tear-down I 14.785s run_tests_on_device(07db034a0075fb61) [==========] 28 tests from 4 test suites ran. (180 ms total) I 14.785s run_tests_on_device(07db034a0075fb61) [ PASSED ] 28 tests. I 14.785s run_tests_on_device(07db034a0075fb61) <<ScopedMainEntryLogger I 14.787s run_tests_on_device(07db034a0075fb61) Finished running tests on this device. I 14.788s Main FINISHED TRY #1/3 I 14.788s Main All tests completed. C 14.789s Main ******************************************************************************** C 14.789s Main Summary C 14.789s Main ******************************************************************************** C 14.789s Main [==========] 28 tests ran. C 14.789s Main [ PASSED ] 28 tests. C 14.789s Main ******************************************************************************** I 14.790s tear_down_device(07db034a0075fb61) Wrote device cache: /b/swarming/w/ir/out/Debug/device_cache_07db034a0075fb61.json I 14.791s Main Generated json results file at /b/swarming/w/itnt6t1X/tmpZ2ulmP I 14.792s Main Finishing archiving output. [W2019-03-24T07:48:05.354168Z 9153 0 butler.go:240] Butler Context was cancelled. Initiating shutdown. {"error":"context canceled"} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' not met [E2019-03-24T07:48:05.394517Z 9153 0 main.go:205] Butler terminated with error. {"error":"context canceled"} [E2019-03-24T07:48:05.394602Z 9153 0 main.go:233] Failed to serve. original error: context canceled [I2019-03-24T07:48:05.394874Z 9153 0 main.go:349] Terminating. {"returnCode":250} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' met 2019-03-24 13:23:48,545 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpEXGqGN/43ca2e7c018a1410'] 2019-03-24 13:23:48,545 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpEXGqGN/43ca2e7c018a1410/output.json'] 2019-03-24 13:23:48,545 - 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": "swarm96-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553458773474746, "id": "8918074129104160064", "project": "chromium", "tags": ["build_address:luci.chromium.ci/KitKat Phone Tester (dbg)/12595", "builder:KitKat Phone Tester (dbg)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/df4289eaea2d4b063d3076eca0eba4e3212e0505", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:40678", "scheduler_invocation_id:9083504191217821536", "scheduler_job_id:chromium/KitKat Phone Tester (dbg)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "KitKat Phone Tester (dbg)", "buildnumber": 12595, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "got_revision_cp": "refs/heads/master@{#643734}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "parent_got_revision_cp": "refs/heads/master@{#643734}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "swarm_hashes": {"android_webview_unittests": "6af6a6f75f5c03f5e129008662b68809d2d3392e", "angle_unittests": "e7efb4707bf26013053b327c04118843a732f8ac", "base_unittests": "fd839d7f53df410527455e907c1efd79750f1d90", "blink_common_unittests": "e261912aea9eb2807d4bde1a233a33f54b1c7ee2", "blink_heap_unittests": "bb1c5bd1e759899695cd96da5ac1cdaf9dceb4c6", "blink_platform_unittests": "f3294564ba6e09d218b4448844031442ef4b7ce4", "blink_unittests": "d6bb1251dfe57861b989221a4d2c296bd0502eed", "blink_web_tests_exparchive": "d24ebd06e1e2ebe75938aea56a644af20f77bfd3", "boringssl_crypto_tests": "e610f52557dd9c9359226e1b8f35dfba02c8a9cf", "boringssl_ssl_tests": "11dcc6fe11e60d84ed98c7d0393f4946aa1135dd", "breakpad_unittests": "9ed215e237069e2af7a9fb7924e4891798ab9891", "cacheinvalidation_unittests": "39326f18e2fc58d6ff7f231440ba89ed6933fc56", "capture_unittests": "53347a669cbcc189381a6a68eb5a836d522918c7", "cast_unittests": "04506375dd5cd8bb497b8ee39949daa9258545bb", "cc_unittests": "80bb7b5d090f24d326360e4e0ac07e6caea3a27e", "chrome_public_test_apk": "21cb43e818c76ff8e0136f8c335b9daeb810a964", "chrome_public_test_vr_apk": "4a7ec2edfe1aa4d41b1de3e8c901c5b779ec4f09", "components_browsertests": "b3d597df9dea7ec26e3fc0c194c5add0850c80b3", "components_unittests": "2b8dd2251b7ee23fe4e90ed24e0b50c6922f9099", "content_browsertests": "a3e11a4efa4d3f4858e8e569977bd72ce4ab8292", "content_shell_test_apk": "5f413df7c148fc1d9edb24c70a7d627cae69deeb", "content_unittests": "079c18bfd666d0f992dda0118b99fc8ca81fa190", "crypto_unittests": "fb215959e791c80bf0a129c014f8a2b785731cc0", "device_unittests": "9fed47a69ac27290353154c8832ea2a76c5ef8be", "display_unittests": "6384452d164ea1495515225d11808aeab391aa5c", "events_unittests": "668ddbc2836a82cac5d9eaae397df5f6b33b7879", "gcm_unit_tests": "b49a09cb59d7bfeb6ba0e3b0c987edb3c3688d8f", "gfx_unittests": "bd1eaf76bd8c1768be9acb471746ab27c1ee2e75", "gin_unittests": "22cf6b8d5296ea06669231fb3615882e49dc90b0", "gl_tests": "0ebbaccc5298b07253a0931798568d23a3859d56", "gl_unittests": "7111c8b5b7d572ee626ec9b573dabff69b42b972", "google_apis_unittests": "304b1ff801a741f4b0dacc59c27e6091a0f0c8e7", "gpu_unittests": "4c4db615ca664a5b4da15b27a5cc68c086a51c97", "ipc_tests": "da925b70a469d8abed331a6ea58001110f5d5024", "jingle_unittests": "bf443306a821e405c65677eed075507dfac48267", "latency_unittests": "31cf451aa44e410b40652e2dd305ff156969bf85", "libjingle_xmpp_unittests": "09ad97caad60b8bff22f1ecad61bc90e71cbc2ee", "media_blink_unittests": "325ba3d03495dd68bb3512ab7881b70f4400b224", "media_service_unittests": "59775ba6b921e7247bde77c0eb9aa6ee1afef5ad", "media_unittests": "60da53915af74a9627134de49cda4f2a340a6216", "midi_unittests": "33b932da453c467175e9dc624afaf8af96316724", "mojo_test_apk": "874fc4649f6a8c30b8ad69fb357bc0c161082228", "mojo_unittests": "938f03f812a8766c483e90dc8178a5da7686ea46", "net_unittests": "ddaf1a18b6ffe608ea1d641c4537e5af1a29d951", "sandbox_linux_unittests": "2008bfd31568136e1c4300245b4c8523fca591f3", "services_unittests": "fb19ba2729306469977504cc03358038192822a0", "shell_dialogs_unittests": "ab267e95a1c9bae06fe6df277abc74c39736aa28", "skia_unittests": "710e85ebc7310ce3c822449c19329e8a4afcb372", "sql_unittests": "6b5e5879dd86debc2abc26906d08b8593cbb0778", "storage_unittests": "a8d61f20d54e79d2c19f4358484394cc1ab51d1a", "ui_android_unittests": "8770bb930b654f54acc4c179c3be6cbc354eea00", "ui_base_unittests": "7d56a4f685e4ebf6bc0b4496713bfdc574aaa2df", "ui_touch_selection_unittests": "1c3304e77ce712a670512612cf5b14d40c83480e", "unit_tests": "4fae2743a34d5f87513fd399a82f5b49ac6ca2c3", "url_unittests": "4aec20ba11887695a2274def456318ea654c58d1", "viz_unittests": "6f942d64e003b8e33a2f9ce2ce94e061e0cba4d1", "vr_android_unittests": "81473302290011955a630c10f6c9b637e4188e48", "vr_common_unittests": "31c3b3c6e7f6ec184bcc08f7aff0cf082933c46a", "vr_pixeltests": "a62ff6a6b6bd33efc5e383fb95af843b7f73ff8b", "webview_cts_tests": "5ab5f62605c908b55d4bf0a8a7a80b4e3da8b349", "webview_instrumentation_test_apk": "6c6628e7b523d6537116b62673604435a4a8c106", "wtf_unittests": "ac51da88ad8e912387a8927548b97443750171c9"}} --summary-json /b/swarming/w/ir/tmp/t/tmprLD7Q7.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpEXGqGN --bucket chromium-result-details --test-name cacheinvalidation_unittests -o /b/swarming/w/ir/tmp/t/tmphZzIgv.json /b/swarming/w/ir/tmp/t/tmpEXGqGN/43ca2e7c018a1410/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": "swarm96-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553458773474746, "id": "8918074129104160064", "project": "chromium", "tags": ["build_address:luci.chromium.ci/KitKat Phone Tester (dbg)/12595", "builder:KitKat Phone Tester (dbg)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/df4289eaea2d4b063d3076eca0eba4e3212e0505", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:40678", "scheduler_invocation_id:9083504191217821536", "scheduler_job_id:chromium/KitKat Phone Tester (dbg)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "KitKat Phone Tester (dbg)", "buildnumber": 12595, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "got_revision_cp": "refs/heads/master@{#643734}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "parent_got_revision_cp": "refs/heads/master@{#643734}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "swarm_hashes": {"android_webview_unittests": "6af6a6f75f5c03f5e129008662b68809d2d3392e", "angle_unittests": "e7efb4707bf26013053b327c04118843a732f8ac", "base_unittests": "fd839d7f53df410527455e907c1efd79750f1d90", "blink_common_unittests": "e261912aea9eb2807d4bde1a233a33f54b1c7ee2", "blink_heap_unittests": "bb1c5bd1e759899695cd96da5ac1cdaf9dceb4c6", "blink_platform_unittests": "f3294564ba6e09d218b4448844031442ef4b7ce4", "blink_unittests": "d6bb1251dfe57861b989221a4d2c296bd0502eed", "blink_web_tests_exparchive": "d24ebd06e1e2ebe75938aea56a644af20f77bfd3", "boringssl_crypto_tests": "e610f52557dd9c9359226e1b8f35dfba02c8a9cf", "boringssl_ssl_tests": "11dcc6fe11e60d84ed98c7d0393f4946aa1135dd", "breakpad_unittests": "9ed215e237069e2af7a9fb7924e4891798ab9891", "cacheinvalidation_unittests": "39326f18e2fc58d6ff7f231440ba89ed6933fc56", "capture_unittests": "53347a669cbcc189381a6a68eb5a836d522918c7", "cast_unittests": "04506375dd5cd8bb497b8ee39949daa9258545bb", "cc_unittests": "80bb7b5d090f24d326360e4e0ac07e6caea3a27e", "chrome_public_test_apk": "21cb43e818c76ff8e0136f8c335b9daeb810a964", "chrome_public_test_vr_apk": "4a7ec2edfe1aa4d41b1de3e8c901c5b779ec4f09", "components_browsertests": "b3d597df9dea7ec26e3fc0c194c5add0850c80b3", "components_unittests": "2b8dd2251b7ee23fe4e90ed24e0b50c6922f9099", "content_browsertests": "a3e11a4efa4d3f4858e8e569977bd72ce4ab8292", "content_shell_test_apk": "5f413df7c148fc1d9edb24c70a7d627cae69deeb", "content_unittests": "079c18bfd666d0f992dda0118b99fc8ca81fa190", "crypto_unittests": "fb215959e791c80bf0a129c014f8a2b785731cc0", "device_unittests": "9fed47a69ac27290353154c8832ea2a76c5ef8be", "display_unittests": "6384452d164ea1495515225d11808aeab391aa5c", "events_unittests": "668ddbc2836a82cac5d9eaae397df5f6b33b7879", "gcm_unit_tests": "b49a09cb59d7bfeb6ba0e3b0c987edb3c3688d8f", "gfx_unittests": "bd1eaf76bd8c1768be9acb471746ab27c1ee2e75", "gin_unittests": "22cf6b8d5296ea06669231fb3615882e49dc90b0", "gl_tests": "0ebbaccc5298b07253a0931798568d23a3859d56", "gl_unittests": "7111c8b5b7d572ee626ec9b573dabff69b42b972", "google_apis_unittests": "304b1ff801a741f4b0dacc59c27e6091a0f0c8e7", "gpu_unittests": "4c4db615ca664a5b4da15b27a5cc68c086a51c97", "ipc_tests": "da925b70a469d8abed331a6ea58001110f5d5024", "jingle_unittests": "bf443306a821e405c65677eed075507dfac48267", "latency_unittests": "31cf451aa44e410b40652e2dd305ff156969bf85", "libjingle_xmpp_unittests": "09ad97caad60b8bff22f1ecad61bc90e71cbc2ee", "media_blink_unittests": "325ba3d03495dd68bb3512ab7881b70f4400b224", "media_service_unittests": "59775ba6b921e7247bde77c0eb9aa6ee1afef5ad", "media_unittests": "60da53915af74a9627134de49cda4f2a340a6216", "midi_unittests": "33b932da453c467175e9dc624afaf8af96316724", "mojo_test_apk": "874fc4649f6a8c30b8ad69fb357bc0c161082228", "mojo_unittests": "938f03f812a8766c483e90dc8178a5da7686ea46", "net_unittests": "ddaf1a18b6ffe608ea1d641c4537e5af1a29d951", "sandbox_linux_unittests": "2008bfd31568136e1c4300245b4c8523fca591f3", "services_unittests": "fb19ba2729306469977504cc03358038192822a0", "shell_dialogs_unittests": "ab267e95a1c9bae06fe6df277abc74c39736aa28", "skia_unittests": "710e85ebc7310ce3c822449c19329e8a4afcb372", "sql_unittests": "6b5e5879dd86debc2abc26906d08b8593cbb0778", "storage_unittests": "a8d61f20d54e79d2c19f4358484394cc1ab51d1a", "ui_android_unittests": "8770bb930b654f54acc4c179c3be6cbc354eea00", "ui_base_unittests": "7d56a4f685e4ebf6bc0b4496713bfdc574aaa2df", "ui_touch_selection_unittests": "1c3304e77ce712a670512612cf5b14d40c83480e", "unit_tests": "4fae2743a34d5f87513fd399a82f5b49ac6ca2c3", "url_unittests": "4aec20ba11887695a2274def456318ea654c58d1", "viz_unittests": "6f942d64e003b8e33a2f9ce2ce94e061e0cba4d1", "vr_android_unittests": "81473302290011955a630c10f6c9b637e4188e48", "vr_common_unittests": "31c3b3c6e7f6ec184bcc08f7aff0cf082933c46a", "vr_pixeltests": "a62ff6a6b6bd33efc5e383fb95af843b7f73ff8b", "webview_cts_tests": "5ab5f62605c908b55d4bf0a8a7a80b4e3da8b349", "webview_instrumentation_test_apk": "6c6628e7b523d6537116b62673604435a4a8c106", "wtf_unittests": "ac51da88ad8e912387a8927548b97443750171c9"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmprLD7Q7.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpEXGqGN', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmphZzIgv.json', '/b/swarming/w/ir/tmp/t/tmpEXGqGN/43ca2e7c018a1410/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": "swarm96-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553458773474746, "id": "8918074129104160064", "project": "chromium", "tags": ["build_address:luci.chromium.ci/KitKat Phone Tester (dbg)/12595", "builder:KitKat Phone Tester (dbg)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/df4289eaea2d4b063d3076eca0eba4e3212e0505", "gitiles_ref:refs/heads/master", "parent_buildername:Android arm Builder (dbg)", "parent_buildnumber:40678", "scheduler_invocation_id:9083504191217821536", "scheduler_job_id:chromium/KitKat Phone Tester (dbg)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "KitKat Phone Tester (dbg)", "buildnumber": 12595, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "got_revision_cp": "refs/heads/master@{#643734}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.android", "parent_buildername": "Android arm Builder (dbg)", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "parent_got_revision_cp": "refs/heads/master@{#643734}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "revision": "df4289eaea2d4b063d3076eca0eba4e3212e0505", "swarm_hashes": {"android_webview_unittests": "6af6a6f75f5c03f5e129008662b68809d2d3392e", "angle_unittests": "e7efb4707bf26013053b327c04118843a732f8ac", "base_unittests": "fd839d7f53df410527455e907c1efd79750f1d90", "blink_common_unittests": "e261912aea9eb2807d4bde1a233a33f54b1c7ee2", "blink_heap_unittests": "bb1c5bd1e759899695cd96da5ac1cdaf9dceb4c6", "blink_platform_unittests": "f3294564ba6e09d218b4448844031442ef4b7ce4", "blink_unittests": "d6bb1251dfe57861b989221a4d2c296bd0502eed", "blink_web_tests_exparchive": "d24ebd06e1e2ebe75938aea56a644af20f77bfd3", "boringssl_crypto_tests": "e610f52557dd9c9359226e1b8f35dfba02c8a9cf", "boringssl_ssl_tests": "11dcc6fe11e60d84ed98c7d0393f4946aa1135dd", "breakpad_unittests": "9ed215e237069e2af7a9fb7924e4891798ab9891", "cacheinvalidation_unittests": "39326f18e2fc58d6ff7f231440ba89ed6933fc56", "capture_unittests": "53347a669cbcc189381a6a68eb5a836d522918c7", "cast_unittests": "04506375dd5cd8bb497b8ee39949daa9258545bb", "cc_unittests": "80bb7b5d090f24d326360e4e0ac07e6caea3a27e", "chrome_public_test_apk": "21cb43e818c76ff8e0136f8c335b9daeb810a964", "chrome_public_test_vr_apk": "4a7ec2edfe1aa4d41b1de3e8c901c5b779ec4f09", "components_browsertests": "b3d597df9dea7ec26e3fc0c194c5add0850c80b3", "components_unittests": "2b8dd2251b7ee23fe4e90ed24e0b50c6922f9099", "content_browsertests": "a3e11a4efa4d3f4858e8e569977bd72ce4ab8292", "content_shell_test_apk": "5f413df7c148fc1d9edb24c70a7d627cae69deeb", "content_unittests": "079c18bfd666d0f992dda0118b99fc8ca81fa190", "crypto_unittests": "fb215959e791c80bf0a129c014f8a2b785731cc0", "device_unittests": "9fed47a69ac27290353154c8832ea2a76c5ef8be", "display_unittests": "6384452d164ea1495515225d11808aeab391aa5c", "events_unittests": "668ddbc2836a82cac5d9eaae397df5f6b33b7879", "gcm_unit_tests": "b49a09cb59d7bfeb6ba0e3b0c987edb3c3688d8f", "gfx_unittests": "bd1eaf76bd8c1768be9acb471746ab27c1ee2e75", "gin_unittests": "22cf6b8d5296ea06669231fb3615882e49dc90b0", "gl_tests": "0ebbaccc5298b07253a0931798568d23a3859d56", "gl_unittests": "7111c8b5b7d572ee626ec9b573dabff69b42b972", "google_apis_unittests": "304b1ff801a741f4b0dacc59c27e6091a0f0c8e7", "gpu_unittests": "4c4db615ca664a5b4da15b27a5cc68c086a51c97", "ipc_tests": "da925b70a469d8abed331a6ea58001110f5d5024", "jingle_unittests": "bf443306a821e405c65677eed075507dfac48267", "latency_unittests": "31cf451aa44e410b40652e2dd305ff156969bf85", "libjingle_xmpp_unittests": "09ad97caad60b8bff22f1ecad61bc90e71cbc2ee", "media_blink_unittests": "325ba3d03495dd68bb3512ab7881b70f4400b224", "media_service_unittests": "59775ba6b921e7247bde77c0eb9aa6ee1afef5ad", "media_unittests": "60da53915af74a9627134de49cda4f2a340a6216", "midi_unittests": "33b932da453c467175e9dc624afaf8af96316724", "mojo_test_apk": "874fc4649f6a8c30b8ad69fb357bc0c161082228", "mojo_unittests": "938f03f812a8766c483e90dc8178a5da7686ea46", "net_unittests": "ddaf1a18b6ffe608ea1d641c4537e5af1a29d951", "sandbox_linux_unittests": "2008bfd31568136e1c4300245b4c8523fca591f3", "services_unittests": "fb19ba2729306469977504cc03358038192822a0", "shell_dialogs_unittests": "ab267e95a1c9bae06fe6df277abc74c39736aa28", "skia_unittests": "710e85ebc7310ce3c822449c19329e8a4afcb372", "sql_unittests": "6b5e5879dd86debc2abc26906d08b8593cbb0778", "storage_unittests": "a8d61f20d54e79d2c19f4358484394cc1ab51d1a", "ui_android_unittests": "8770bb930b654f54acc4c179c3be6cbc354eea00", "ui_base_unittests": "7d56a4f685e4ebf6bc0b4496713bfdc574aaa2df", "ui_touch_selection_unittests": "1c3304e77ce712a670512612cf5b14d40c83480e", "unit_tests": "4fae2743a34d5f87513fd399a82f5b49ac6ca2c3", "url_unittests": "4aec20ba11887695a2274def456318ea654c58d1", "viz_unittests": "6f942d64e003b8e33a2f9ce2ce94e061e0cba4d1", "vr_android_unittests": "81473302290011955a630c10f6c9b637e4188e48", "vr_common_unittests": "31c3b3c6e7f6ec184bcc08f7aff0cf082933c46a", "vr_pixeltests": "a62ff6a6b6bd33efc5e383fb95af843b7f73ff8b", "webview_cts_tests": "5ab5f62605c908b55d4bf0a8a7a80b4e3da8b349", "webview_instrumentation_test_apk": "6c6628e7b523d6537116b62673604435a4a8c106", "wtf_unittests": "ac51da88ad8e912387a8927548b97443750171c9"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmprLD7Q7.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpEXGqGN', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmphZzIgv.json', '/b/swarming/w/ir/tmp/t/tmpEXGqGN/43ca2e7c018a1410/output.json'] returned exit code 0