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

{ "shards": [ { "bot_dimensions": [ { "key": "android_devices", "value": [ "1" ] }, { "key": "caches", "value": [ "swarming_module_cache_vpython" ] }, { "key": "cpu_governor", "value": [ "powersave" ] }, { "key": "device_gms_core_version", "value": [ "4.3.23" ] }, { "key": "device_os", "value": [ "K", "KTU84P" ] }, { "key": "device_os_flavor", "value": [ "google" ] }, { "key": "device_playstore_version", "value": [ "4.5.10" ] }, { "key": "device_type", "value": [ "hammerhead" ] }, { "key": "gce", "value": [ "0" ] }, { "key": "id", "value": [ "build292-m1--device2" ] }, { "key": "inside_docker", "value": [ "1", "stock" ] }, { "key": "locale", "value": [ "en_US.UTF-8" ] }, { "key": "os", "value": [ "Android" ] }, { "key": "pool", "value": [ "Chrome" ] }, { "key": "python", "value": [ "2.7.12" ] }, { "key": "server_version", "value": [ "4211-90dafba" ] }, { "key": "temp_band", "value": [ "<30" ] }, { "key": "zone", "value": [ "us", "us-golo", "us-golo-1" ] } ], "bot_id": "build292-m1--device2", "bot_version": "a1949c9c9626232734f8c6a011db49db86c0d07bdcf5444a07f04046abeaa3cd", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "nFftZl2kFquaI2EUmPGwzbc5sIbCocl9L55UeASqlLsC" }, "packages": [ { "package_name": "infra/python/cpython/linux-amd64", "path": ".swarming_module", "version": "46c0c897ca0f053799ee41fd148bb7a47232df47" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": ".swarming_module", "version": "2737ea8ed9b958f4d5aa9ffe106115a649ada241" }, { "package_name": "infra/tools/luci/vpython-native/linux-amd64", "path": ".swarming_module", "version": "OAXVAmcUSrvDygYUrCDzv20LRono9938YOHPu0zKowgC" }, { "package_name": "infra/tools/luci/vpython/linux-amd64", "path": ".swarming_module", "version": "ucaOciwAE9aweCUDOrmSvyiwrjmbywuB0NzAGUXIHjAC" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": "bin", "version": "a57ad614c01fec9fa4259473c8ea3fd992d7c349" } ] }, "completed_ts": "2019-03-21T16:45:17.448108", "cost_saved_usd": 0.002618901838385953, "created_ts": "2019-03-21T17:31:03.761836", "deduped_from": "43b9f5a9720a5911", "duration": 15.446111917495728, "modified_ts": "2019-03-21T17:31:03.772142", "name": "cacheinvalidation_unittests on Android device Nexus 5/Android/d6809e29db/android-kitkat-arm-rel/15664", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n LANG=en_US.UTF-8\nCommand: /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/ioHokYPm/output.json\n\nI 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/ioHokYPm/output.json\nI 0.007s Main condition '<lambda>' met\nI 0.008s Main condition '<lambda>' met\nI 3.094s TimeoutThread-1-for-prepare_device(05fc91a30ae56c8b) condition 'sd_card_ready' met (0.0s)\nI 3.624s TimeoutThread-1-for-prepare_device(05fc91a30ae56c8b) condition 'pm_ready' met (0.5s)\nI 3.633s TimeoutThread-1-for-prepare_device(05fc91a30ae56c8b) condition 'boot_completed' met (0.5s)\nI 6.518s calculate_device_checksums condition '<lambda>' met (0.1s)\nI 7.524s list_tests(05fc91a30ae56c8b) flags:\nI 7.524s list_tests(05fc91a30ae56c8b) --gtest_list_tests\nI 8.624s list_tests(05fc91a30ae56c8b) /storage/emulated/legacy/temp_file-981461b3be83f.gtest_out size on device: 682\nI 8.693s Main Using external sharding settings. This is shard 0/1\nI 8.694s Main STARTING TRY #1/3\nI 8.694s Main Will run 28 tests on 1 devices: 05fc91a30ae56c8b\nI 10.698s run_tests_on_device(05fc91a30ae56c8b) flags:\nI 10.699s run_tests_on_device(05fc91a30ae56c8b) Getting logdog client.\nI 12.252s run_tests_on_device(05fc91a30ae56c8b) /storage/emulated/legacy/temp_file-86eea46538fea.gtest_out size on device: 95693\nI 12.526s run_tests_on_device(05fc91a30ae56c8b) Logcat saved to https://luci-logdog.appspot.com/v/?s=chromium%2Fandroid%2Fswarming%2Flogcats%2F43b9f5a9720a5911%2F%2B%2Flogcat_logcat_-2631999291401687399_20190321T164512-UTC_05fc91a30ae56c8b\nI 12.527s archive Writing text to logdog stream, logcat_logcat_-2631999291401687399_20190321T164512-UTC_05fc91a30ae56c8b\nI 13.094s run_tests_on_device(05fc91a30ae56c8b) >>ScopedMainEntryLogger\nI 13.094s run_tests_on_device(05fc91a30ae56c8b) 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\nI 13.094s run_tests_on_device(05fc91a30ae56c8b) [==========] Running 28 tests from 4 test suites.\nI 13.094s run_tests_on_device(05fc91a30ae56c8b) [----------] Global test environment set-up.\nI 13.094s run_tests_on_device(05fc91a30ae56c8b) [----------] 10 tests from InvalidationClientImplTest\nI 13.094s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.Start\nI 13.094s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 536940544) Enqueuing 0xc926000 with delay 181\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1969691391) Enqueuing 0xc926000 with delay 181\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970823456) Running task 0xc926000\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970823456) Running task 0xc926000\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970823456) Running task 0xc926000\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970823456) Running task 0xc926000\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.095s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970828184 with a delay 1074834445, Now = 0\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970823456) Running task 0xc926000\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1511172752066889587\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970828572 with a delay -1090589008, Now = 500000\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970828184 with a delay -2147483632, Now = 60000000\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970823456) Running task 0xc9a0120\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [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: \"1511172752066889587\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.096s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970832776) Enqueuing 0xc9a0120 with delay 181\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1511172752066889587\" 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\" } }\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1511172752066889587\"\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970828500 with a delay -1090589064, Now = 1200000000\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970828472 with a delay -1090589064, Now = 0\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.097s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970828472 with a delay 0, Now = 10000000\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.Start (6 ms)\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.GenerateNonce\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 200704) Enqueuing 0xc926000 with delay 181\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.Register\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 200704) Enqueuing 0xc926000 with delay 181\nI 13.098s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970140969) Enqueuing 0xc926000 with delay 181\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970830232 with a delay 1074834445, Now = 0\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.099s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4435476624740729599\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970830620 with a delay -1090589272, Now = 500000\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830232 with a delay -2147483632, Now = 60000000\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc9a0120\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [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: \"-4435476624740729599\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970835392) Enqueuing 0xc9a0120 with delay 181\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.100s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4435476624740729599\" 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\" } }\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4435476624740729599\"\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970830548 with a delay -1090589328, Now = 1200000000\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970830520 with a delay -1090589328, Now = 0\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830520 with a delay 0, Now = 10000000\nI 13.101s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc9ac470\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1970830620 with a delay 1032960, Now = 500000\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1970830400 with a delay 3, Now = 60000000\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xca26590\nI 13.102s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [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 } } }\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970841352) Enqueuing 0xca26590 with delay 181\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [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 } } } }\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\nI 13.103s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.Register (8 ms)\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.Invalidations\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 200704) Enqueuing 0xc926000 with delay 181\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970140969) Enqueuing 0xc926000 with delay 181\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.104s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970830352 with a delay 1074834445, Now = 0\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc926000\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-5572501457722652409\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970830740 with a delay -1090589304, Now = 500000\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830352 with a delay -2147483632, Now = 60000000\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.105s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc9a0120\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [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: \"-5572501457722652409\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970836448) Enqueuing 0xc9a0120 with delay 181\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-5572501457722652409\" 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\" } }\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-5572501457722652409\"\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970830668 with a delay -1090589360, Now = 1200000000\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.106s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970830640 with a delay -1090589360, Now = 0\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830640 with a delay 0, Now = 10000000\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970176199) Enqueuing 0xc9ac470 with delay 181\nI 13.107s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [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 } } }\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [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\" }\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true }\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true }\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970839164) Enqueuing 0xc9b87c0 with delay 181\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970839164) Enqueuing 0xc9b87c0 with delay 181\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970839164) Enqueuing 0xc9b87c0 with delay 181\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc9b87c0\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1970830740 with a delay 1074834425, Now = 500000\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9b87c0 with delay 181\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc9b87c0\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xc9b87c0\nI 13.108s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825520) Running task 0xca328e0\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [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 } } }\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.Invalidations (8 ms)\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.ServerRequests\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 537071616) Enqueuing 0xc926000 with delay 181\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588336) Enqueuing 0xc926000 with delay 181\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.109s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970829720 with a delay 1074834445, Now = 0\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4636564601240016304\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970830108 with a delay -1090589160, Now = 500000\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829720 with a delay -2147483632, Now = 60000000\nI 13.110s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9a0120\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [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: \"4636564601240016304\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970834312) Enqueuing 0xc9a0120 with delay 181\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4636564601240016304\" 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\" } }\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4636564601240016304\"\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970830036 with a delay -1090589216, Now = 1200000000\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.111s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970830008 with a delay -1090589216, Now = 0\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830008 with a delay 0, Now = 10000000\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc9ac470 with delay 181\nI 13.112s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(294)] Adding subtree: { }\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 1970830108 with a delay -1090589184, Now = 500000\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 13.113s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.ServerRequests (7 ms)\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 537071616) Enqueuing 0xc926000 with delay 181\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970140969) Enqueuing 0xc926000 with delay 181\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.114s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970829720 with a delay 1074834445, Now = 0\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4634181773183950779\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970830108 with a delay -1090589120, Now = 500000\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829720 with a delay -2147483632, Now = 60000000\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9a0120\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.115s run_tests_on_device(05fc91a30ae56c8b) [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: \"-4634181773183950779\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970834760) Enqueuing 0xc9a0120 with delay 181\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4634181773183950779\" 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\" } }\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4634181773183950779\"\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970830036 with a delay -1090589176, Now = 1200000000\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970830008 with a delay -1090589176, Now = 0\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.116s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830008 with a delay 0, Now = 10000000\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc9ac470 with delay 181\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.IncomingErrorMessage (7 ms)\nI 13.117s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 537071616) Enqueuing 0xc926000 with delay 181\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970140969) Enqueuing 0xc926000 with delay 181\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970829720 with a delay 1074834445, Now = 0\nI 13.118s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-5856242677894171679\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970830108 with a delay -1090589248, Now = 500000\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829720 with a delay -2147483632, Now = 60000000\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9a0120\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [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: \"-5856242677894171679\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970835496) Enqueuing 0xc9a0120 with delay 181\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.119s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-5856242677894171679\" 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\" } }\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-5856242677894171679\"\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970830036 with a delay -1090589304, Now = 1200000000\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970830008 with a delay -1090589304, Now = 0\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830008 with a delay 0, Now = 10000000\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.120s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9ac470\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1970830108 with a delay 270787635, Now = 500000\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1970829888 with a delay 1, Now = 60000000\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xca26590\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [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 } } }\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xca26590 with delay 181\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (8 ms)\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.NetworkTimeouts\nI 13.121s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 537071616) Enqueuing 0xc926000 with delay 181\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588336) Enqueuing 0xc926000 with delay 181\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970829720 with a delay 1074834445, Now = 0\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3580955578612467916\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970830108 with a delay -1090589160, Now = 500000\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829720 with a delay -2147483632, Now = 60000000\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.122s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9a0120\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [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: \"3580955578612467916\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970834400) Enqueuing 0xc9a0120 with delay 181\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3580955578612467916\" 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\" } }\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3580955578612467916\"\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970830036 with a delay -1090589216, Now = 1200000000\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970830008 with a delay -1090589216, Now = 0\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830008 with a delay 0, Now = 10000000\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.123s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9ac470\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1970830108 with a delay 270787635, Now = 500000\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1970829888 with a delay 1, Now = 60000000\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9ac470 with delay 181\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xca26590\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [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 } } }\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xd3297a0\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0x1025e700\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0x102e4b70\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1970830108 with a delay -1090589200, Now = 500000\nI 13.124s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x102e4b70 with delay 181\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829888 with a delay 0, Now = 60000000\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x102e4b70 with delay 181\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0x1035ec90\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.NetworkTimeouts (9 ms)\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 537071616) Enqueuing 0xc926000 with delay 181\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588344) Enqueuing 0xc926000 with delay 181\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970829720 with a delay 1074834445, Now = 0\nI 13.125s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3973319428035553746\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970830108 with a delay -1090589168, Now = 500000\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829720 with a delay -2147483632, Now = 60000000\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9a0120\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [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: \"-3973319428035553746\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970834312) Enqueuing 0xc9a0120 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3973319428035553746\" 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\" } }\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3973319428035553746\"\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970830036 with a delay -1090589224, Now = 1200000000\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970830008 with a delay -1090589224, Now = 0\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970830008 with a delay 0, Now = 10000000\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.126s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc9ac470 with delay 181\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.NoRegistrationSummary (6 ms)\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] InvalidationClientImplTest.Heartbeats\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 537071616) Enqueuing 0xc926000 with delay 181\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588304) Enqueuing 0xc926000 with delay 181\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1936876918) Enqueuing 0xc926000 with delay 181\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970829600 with a delay 1074834445, Now = 0\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc926000\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4366235953032074371\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1970829988 with a delay -1090589128, Now = 500000\nI 13.127s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829600 with a delay -2147483632, Now = 60000000\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824816) Running task 0xc9a0120\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [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: \"-4366235953032074371\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970834152) Enqueuing 0xc9a0120 with delay 181\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4366235953032074371\" 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\" } }\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4366235953032074371\"\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1970829916 with a delay -1090589184, Now = 1200000000\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1970829888 with a delay -1090589184, Now = 0\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [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\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 33) Enqueuing 0xc9a0120 with delay 181\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829888 with a delay 0, Now = 10000000\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc9a0120 with delay 181\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970834060) Running task 0xd3297a0\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970834060) Running task 0x1025e700\nI 13.128s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970834060) Running task 0x54208d20\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1970829988 with a delay -1090589200, Now = 500000\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x54208d20 with delay 181\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970829916 with a delay 12, Now = 1200000000\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x54208d20 with delay 181\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970834060) Running task 0x54282e40\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [ OK ] InvalidationClientImplTest.Heartbeats (13 ms)\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [----------] 10 tests from InvalidationClientImplTest (75 ms total)\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) \nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [----------] 13 tests from ProtocolHandlerTest\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.SendInitializeOnly\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970828792) Enqueuing 0xc926000 with delay 181\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc926000\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1970827372 with a delay -1090589096, Now = 500000\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc9a0120\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.129s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.SendInitializeOnly (2 ms)\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970798864) Enqueuing 0xc926000 with delay 181\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970798864) Enqueuing 0xc926000 with delay 181\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970798864) Enqueuing 0xc926000 with delay 181\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074847339) Enqueuing 0xc926000 with delay 181\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074847339) Enqueuing 0xc926000 with delay 181\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970830704) Enqueuing 0xc926000 with delay 181\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc926000\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1970827372 with a delay -1090589528, Now = 500000\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc926000\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc926000\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc926000\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc926000\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc926000\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970140969) Running task 0xc9a0120\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms)\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage\nI 13.130s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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\" }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.MinorVersionMismatch (0 ms)\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.ConfigMessage\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1970829560) Enqueuing 0xc926000 with delay 181\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1969658287) Running task 0xc926000\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1970827372 with a delay -1090588912, Now = 500000\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1969658287) Running task 0xc9a0120\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.ConfigMessage (10 ms)\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.ErrorMessage\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms)\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.TokenMismatch\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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\" } }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms)\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.TokenMissing\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1969917265) Enqueuing 0xc926000 with delay 181\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1969658287) Running task 0xc926000\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.131s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1970827372 with a delay -1090588744, Now = 500000\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1969658287) Running task 0xc9a0120\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [WARNING:protocol-handler.cc(313)] Unable to build message\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074847339) Enqueuing 0xc926000 with delay 181\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1969658287) Running task 0xc926000\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1970827372 with a delay 63, Now = 500000\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xc926000 with delay 181\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1969658287) Running task 0xc9a0120\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [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 }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [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 } }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [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 } } }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [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 } } }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:protocol-handler.cc(139)] Incoming message: { }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ERROR:ticl-message-validator.cc(361)] required field header missing from { }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ERROR:protocol-handler.cc(145)] Received invalid message: { }\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [----------] 13 tests from ProtocolHandlerTest (29 ms total)\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) \nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [----------] 3 tests from RecurringTaskTest\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] RecurringTaskTest.PeriodicTask\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1970824904 with a delay 1970788293, Now = 10000\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x0 with delay 0\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x2710\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 10000\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824904 with a delay 1970669872, Now = 60000\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x2710 with delay 0\nI 13.132s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x11170\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 70000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824904 with a delay 1970669872, Now = 60000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x11170 with delay 0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x1fbd0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 130000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824904 with a delay 1970669872, Now = 60000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x1fbd0 with delay 0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x2e630\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 190000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824904 with a delay 1970669872, Now = 60000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x2e630 with delay 0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x3d090\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 250000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824904 with a delay 1970669872, Now = 60000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3d090 with delay 0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x4baf0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 310000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824904 with a delay 1970669872, Now = 60000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x4baf0 with delay 0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x5a550\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 370000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824904 with a delay 1970669872, Now = 60000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x5a550 with delay 0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824928) Running task 0x68fb0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 430000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [ OK ] RecurringTaskTest.PeriodicTask (4 ms)\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] RecurringTaskTest.ExponentialBackoffTask\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1970824936 with a delay 1, Now = 10000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x0 with delay 0\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0x2710\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 10000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824936 with a delay 1970669872, Now = 50000\nI 13.133s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x2710 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0xea60\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 60000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824936 with a delay 1970669872, Now = 149000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xea60 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0x33450\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 210000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824936 with a delay 1970669872, Now = 248000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x33450 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0x704e0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 460000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824936 with a delay 1970669872, Now = 446000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x704e0 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0xde2b0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 910000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824936 with a delay 1970669872, Now = 842000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xde2b0 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0x1adb00\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 1760000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824936 with a delay 1970669872, Now = 1040000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x1adb00 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0x2ab980\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 2800000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1970824936 with a delay 1970669872, Now = 1040000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x2ab980 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825016) Running task 0x3a9800\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 3840000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [ OK ] RecurringTaskTest.ExponentialBackoffTask (4 ms)\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] RecurringTaskTest.OneShotTask\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1970824904 with a delay 1074834445, Now = 10000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x0 with delay 0\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970824952) Running task 0x2710\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 10000\nI 13.134s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1970824904 with a delay 0, Now = 10000\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x2710 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 1970825056) Running task 0x4e20\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:recurring-task_test.cc(71)] (1970819888) Task running: 20000\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [ OK ] RecurringTaskTest.OneShotTask (1 ms)\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [----------] 3 tests from RecurringTaskTest (10 ms total)\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) \nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [----------] 2 tests from ThrottleTest\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ThrottleTest.ThrottlingScripted\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 2) Enqueuing 0x13880 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xe4e1c0 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ThrottleTest.ThrottlingScripted (1 ms)\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [ RUN ] ThrottleTest.ThrottlingStorm\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 2) Enqueuing 0x2710 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xf4240 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x1e8480\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x1e8480 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x2dc6c0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x2dc6c0 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d0900\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3d0900 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x4c4b40\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x4c4b40 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x5b8d80\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588432) Enqueuing 0x5b8d80 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3938700 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3a2c940\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3a2c940 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3b20b80\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3b20b80 with delay 0\nI 13.135s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3c14dc0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3c14dc0 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d09000\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3d09000 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3dfd240\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x3dfd240 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3ef1480\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588432) Enqueuing 0x3ef1480 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7270e00\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x7270e00 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7365040\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x7365040 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7459280\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x7459280 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x754d4c0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x754d4c0 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7641700\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x7641700 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7735940\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0x7735940 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7829b80\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588432) Enqueuing 0x7829b80 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaba9500\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xaba9500 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xac9d740\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xac9d740 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xad91980\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xad91980 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xae85bc0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xae85bc0 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaf79e00\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xaf79e00 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb06e040\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xb06e040 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb162280\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588432) Enqueuing 0xb162280 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe4e1c00\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xe4e1c00 with delay 0\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe5d5e40\nI 13.136s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xe5d5e40 with delay 0\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe6ca080\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xe6ca080 with delay 0\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe7be2c0\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xe7be2c0 with delay 0\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe8b2500\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xe8b2500 with delay 0\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe9a6740\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: 1074848343) Enqueuing 0xe9a6740 with delay 0\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xea9a980\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(33)] (Now: -1090588432) Enqueuing 0xea9a980 with delay 0\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x11e1a300\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [ OK ] ThrottleTest.ThrottlingStorm (10 ms)\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [----------] 2 tests from ThrottleTest (11 ms total)\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) \nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [----------] Global test environment tear-down\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [==========] 28 tests from 4 test suites ran. (128 ms total)\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) [ PASSED ] 28 tests.\nI 13.137s run_tests_on_device(05fc91a30ae56c8b) <<ScopedMainEntryLogger\nI 13.139s run_tests_on_device(05fc91a30ae56c8b) Finished running tests on this device.\nI 13.167s Main FINISHED TRY #1/3\nI 13.167s Main All tests completed.\nC 13.168s Main ********************************************************************************\nC 13.168s Main Summary\nC 13.168s Main ********************************************************************************\nC 13.168s Main [==========] 28 tests ran.\nC 13.168s Main [ PASSED ] 28 tests.\nC 13.168s Main ********************************************************************************\nI 13.170s tear_down_device(05fc91a30ae56c8b) Wrote device cache: /b/swarming/w/ir/out/Release/device_cache_05fc91a30ae56c8b.json\nI 13.173s Main Generated json results file at /b/swarming/w/itFBGPq_/tmpDPrryr\nI 13.173s Main Finishing archiving output.\n[W2019-03-21T16:45:15.108294Z 30037 0 butler.go:240] Butler Context was cancelled. Initiating shutdown. {\"error\":\"context canceled\"}\nINFO:devil.utils.timeout_retry:condition 'logdog_stopped' not met\n[E2019-03-21T16:45:15.208214Z 30037 0 main.go:205] Butler terminated with error. {\"error\":\"context canceled\"}\n[E2019-03-21T16:45:15.208322Z 30037 0 main.go:233] Failed to serve.\noriginal error: context canceled\n\n[I2019-03-21T16:45:15.208621Z 30037 0 main.go:349] Terminating. {\"returnCode\":250}\nINFO:devil.utils.timeout_retry:condition 'logdog_stopped' met\n", "outputs_ref": { "isolated": "e525c0a1ab7383aca7e77cc51f90f9401d4faa54", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43b9f5a9720a5911", "server_versions": [ "4211-90dafba" ], "started_ts": "2019-03-21T16:44:54.328928", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:android-kitkat-arm-rel", "buildnumber:15664", "data:d6809e29db40bd2337120176a6ecb42f381fb3d1", "device_os:KTU84P", "device_type:hammerhead", "master:chromium.android", "name:cacheinvalidation_unittests", "os:Android", "pool:Chrome", "priority:25", "project:chromium", "purpose:CI", "purpose:luci", "purpose:post-commit", "service_account:none", "slavename:swarm265-c4", "spec_name:chromium.ci:android-kitkat-arm-rel", "stepname:cacheinvalidation_unittests on Android device Nexus 5", "swarming.pool.template:none", "swarming.pool.version:5ad47f4bdd06a3d9b74007236f92e40f4e85560f", "user:None" ], "task_id": "43ba1feedc078d10" } ] }