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": "device_gms_core_version", "value": [ "8.1.86" ] }, { "key": "device_os", "value": [ "M", "MMB29Q" ] }, { "key": "device_os_flavor", "value": [ "google" ] }, { "key": "device_playstore_version", "value": [ "5.12.7" ] }, { "key": "device_type", "value": [ "bullhead" ] }, { "key": "gce", "value": [ "0" ] }, { "key": "id", "value": [ "build362-m1--device6" ] }, { "key": "inside_docker", "value": [ "1", "stock" ] }, { "key": "os", "value": [ "Android" ] }, { "key": "pool", "value": [ "Chrome" ] }, { "key": "python", "value": [ "2.7.12" ] }, { "key": "server_version", "value": [ "4016-2f4b7db" ] }, { "key": "temp_band", "value": [ "<30" ] }, { "key": "zone", "value": [ "us", "us-golo", "us-golo-1" ] } ], "bot_id": "build362-m1--device6", "bot_version": "94abce8f46ebe0e9e277942e607229afc1a9f2a6667e2b870f7246a8e5d73939", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "a2dqpK39PjGpFdcdw62OAE0JOJJ9n8J_AXpJHmH0QCIC" }, "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-01-23T04:31:28.693790", "cost_saved_usd": 0.005012175074347445, "created_ts": "2019-01-23T10:06:54.975324", "deduped_from": "4291cb09ca594111", "duration": 30.801580905914307, "modified_ts": "2019-01-23T10:06:55.005821", "name": "cacheinvalidation_unittests on Android device Nexus 5X/Android/d733a03adf/android-marshmallow-arm64-rel/12089", "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/5d5026/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/ioxg9KYG/output.json\n\nI 0.000s Main command: /b/swarming/w/ir/build/android/test_runner.py gtest --suite cacheinvalidation_unittests --output-directory /b/swarming/w/ir/out/Release --runtime-deps-path /b/swarming/w/ir/out/Release/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/ioxg9KYG/output.json\nI 0.006s Main condition '<lambda>' met\nI 0.008s Main condition '<lambda>' met\nI 3.171s TimeoutThread-1-for-prepare_device(01e2ea64a25dba85) condition 'sd_card_ready' met (0.0s)\nI 3.755s TimeoutThread-1-for-prepare_device(01e2ea64a25dba85) condition 'pm_ready' met (0.6s)\nI 3.806s TimeoutThread-1-for-prepare_device(01e2ea64a25dba85) condition 'boot_completed' met (0.7s)\nI 12.199s TimeoutThread-1-for-individual_device_set_up(01e2ea64a25dba85) Setting permissions for org.chromium.native_test.\nI 16.261s calculate_device_checksums condition '<lambda>' met (0.1s)\nI 18.346s list_tests(01e2ea64a25dba85) flags:\nI 18.346s list_tests(01e2ea64a25dba85) --gtest_list_tests\nI 19.895s list_tests(01e2ea64a25dba85) /sdcard/temp_file-81e4961f7940a.gtest_out size on device: 682\nI 19.964s Main Using external sharding settings. This is shard 0/1\nI 19.964s Main STARTING TRY #1/3\nI 19.964s Main Will run 28 tests on 1 devices: 01e2ea64a25dba85\nW 20.027s run_tests_on_device(01e2ea64a25dba85) No tombstones to clear.\nI 22.430s run_tests_on_device(01e2ea64a25dba85) flags:\nI 22.430s run_tests_on_device(01e2ea64a25dba85) Getting logdog client.\nI 24.280s run_tests_on_device(01e2ea64a25dba85) /sdcard/temp_file-641ce190fa3ea.gtest_out size on device: 96958\nI 24.546s run_tests_on_device(01e2ea64a25dba85) Logcat saved to https://luci-logdog.appspot.com/v/?s=chromium%2Fandroid%2Fswarming%2Flogcats%2F4291cb09ca594111%2F%2B%2Flogcat_logcat_-2631999291401687399_20190123T043120-UTC_01e2ea64a25dba85\nI 24.546s archive Writing text to logdog stream, logcat_logcat_-2631999291401687399_20190123T043120-UTC_01e2ea64a25dba85\nI 25.194s TimeoutThread-1-for-run_tests_on_device(01e2ea64a25dba85) Setting permissions for org.chromium.native_test.\nI 28.614s run_tests_on_device(01e2ea64a25dba85) >>ScopedMainEntryLogger\nI 28.614s run_tests_on_device(01e2ea64a25dba85) 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 28.614s run_tests_on_device(01e2ea64a25dba85) [==========] Running 28 tests from 4 test suites.\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [----------] Global test environment set-up.\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [----------] 10 tests from InvalidationClientImplTest\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.Start\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90e8 with delay 0\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 0\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90e8\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9170\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 0\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9170\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253096 with a delay 0, Now = 210919424\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-734041060977082973\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253288 with a delay 500000, Now = 210919424\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 500\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253096 with a delay 60000000, Now = 210919424\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9178 with delay 60000\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9170\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [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: \"-734041060977082973\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9170 with delay 0\nI 28.614s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9170\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-734041060977082973\" 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 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-734041060977082973\"\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672376 with a delay 1200000000, Now = 211419424\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9180 with delay 1200000\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947173768 with a delay 0, Now = 211419424\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90e8 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [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 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90e8\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9190 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947173768 with a delay 10000000, Now = 211419424\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9188 with delay 10000\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9190\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.615s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.Start (12 ms)\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.GenerateNonce\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.GenerateNonce (2 ms)\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.Register\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90e8 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90e8\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9190 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9190\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253384 with a delay 0, Now = 210919424\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9190 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9190\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7744325226242810698\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253096 with a delay 500000, Now = 210919424\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 500\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253384 with a delay 60000000, Now = 210919424\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9188 with delay 60000\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9180\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [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: \"-7744325226242810698\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9180 with delay 0\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9180\nI 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7744325226242810698\" 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 28.615s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7744325226242810698\"\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672376 with a delay 1200000000, Now = 211419424\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9190 with delay 1200000\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947173768 with a delay 0, Now = 211419424\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90e8 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [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 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90e8\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f91a0 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947173768 with a delay 10000000, Now = 211419424\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9198 with delay 10000\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f91a0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f91a0 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7f740f91a0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1959253096 with a delay 500000, Now = 211469424\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f90e8 with delay 500\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1959253576 with a delay 60000000, Now = 211469424\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f9180 with delay 60000\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7f740f90e8\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [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 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7f740f90e8 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7f740f90e8\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [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 28.616s run_tests_on_device(01e2ea64a25dba85) [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 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7f740f9198\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.Register (15 ms)\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.Invalidations\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90d0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9170\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9198 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9198\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 0\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9170\nI 28.616s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253480 with a delay 0, Now = 210919424\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9198 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9198\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1030472572617810786\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253768 with a delay 500000, Now = 210919424\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 500\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253480 with a delay 60000000, Now = 210919424\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9178 with delay 60000\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9170\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [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: \"-1030472572617810786\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9170 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9170\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1030472572617810786\" 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 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1030472572617810786\"\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672824 with a delay 1200000000, Now = 211419424\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9198 with delay 1200000\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947173768 with a delay 0, Now = 211419424\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [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 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f91a8 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947173768 with a delay 10000000, Now = 211419424\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f91a0 with delay 10000\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f91a8\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f91a8 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7f740f91a8\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [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 28.617s run_tests_on_device(01e2ea64a25dba85) [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 28.617s run_tests_on_device(01e2ea64a25dba85) [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 28.617s run_tests_on_device(01e2ea64a25dba85) [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 28.617s run_tests_on_device(01e2ea64a25dba85) [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 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7f740f91a8 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7f740f9170 with delay 0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7f740f91a8\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1959253768 with a delay 500000, Now = 211519424\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7f740f91b0 with delay 500\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7f740f90d0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7f740f9170\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7f740f91b0\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.617s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [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 28.618s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.Invalidations (14 ms)\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.ServerRequests\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9158 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90d0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9158\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9168 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9168\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9158 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9158\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253384 with a delay 0, Now = 210919424\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9168 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9168\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6362057533264050482\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959254248 with a delay 500000, Now = 210919424\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9158 with delay 500\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253384 with a delay 60000000, Now = 210919424\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 60000\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9158\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [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: \"-6362057533264050482\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9158 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9158\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6362057533264050482\" 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 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6362057533264050482\"\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672824 with a delay 1200000000, Now = 211419424\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9168 with delay 1200000\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947174152 with a delay 0, Now = 211419424\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [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 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9180 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947174152 with a delay 10000000, Now = 211419424\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9170 with delay 10000\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9180\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f9180 with delay 0\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7f740f9180\nI 28.618s run_tests_on_device(01e2ea64a25dba85) [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 28.618s run_tests_on_device(01e2ea64a25dba85) [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 28.618s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(294)] Adding subtree: { }\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 1959254248 with a delay 500000, Now = 211469424\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f90d0 with delay 500\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [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 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7f740f90d0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [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 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7f740f9170\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.ServerRequests (13 ms)\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90d8\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9190 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9190\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253768 with a delay 0, Now = 210919424\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9190 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9190\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6934351484719266455\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253384 with a delay 500000, Now = 210919424\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 500\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253768 with a delay 60000000, Now = 210919424\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9188 with delay 60000\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9180\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [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: \"6934351484719266455\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9180 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9180\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6934351484719266455\" 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 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6934351484719266455\"\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672824 with a delay 1200000000, Now = 211419424\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9190 with delay 1200000\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947174152 with a delay 0, Now = 211419424\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [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 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d8\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f91a0 with delay 0\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947174152 with a delay 10000000, Now = 211419424\nI 28.619s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9198 with delay 10000\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f91a0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f91a0 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7f740f91a0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [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 28.620s run_tests_on_device(01e2ea64a25dba85) [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 28.620s run_tests_on_device(01e2ea64a25dba85) [ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7f740f9198\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.IncomingErrorMessage (11 ms)\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90d8\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f91a0 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f91a0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253480 with a delay 0, Now = 210919424\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f91a0 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f91a0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6849215297018952544\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253768 with a delay 500000, Now = 210919424\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 500\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253480 with a delay 60000000, Now = 210919424\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9198 with delay 60000\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9180\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [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: \"-6849215297018952544\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9180 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9180\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6849215297018952544\" 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 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6849215297018952544\"\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672824 with a delay 1200000000, Now = 211419424\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f91a0 with delay 1200000\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947174152 with a delay 0, Now = 211419424\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [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 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d8\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f91b0 with delay 0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947174152 with a delay 10000000, Now = 211419424\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f91a8 with delay 10000\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f91b0\nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.620s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f91b0 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7f740f91b0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1959253768 with a delay 500000, Now = 211469424\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f90d8 with delay 500\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1959253096 with a delay 60000000, Now = 211469424\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f9180 with delay 60000\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7f740f90d8\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [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 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7f740f90d8\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [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 28.621s run_tests_on_device(01e2ea64a25dba85) [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 28.621s run_tests_on_device(01e2ea64a25dba85) [ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7f740f91a8\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (13 ms)\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.NetworkTimeouts\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9158 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90d0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9158\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9168 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9168\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9158 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9158\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253192 with a delay 0, Now = 210919424\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9168 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9168\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2332876986418049732\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253480 with a delay 500000, Now = 210919424\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9158 with delay 500\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253192 with a delay 60000000, Now = 210919424\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 60000\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9158\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [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: \"-2332876986418049732\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9158 with delay 0\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9158\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2332876986418049732\" 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 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2332876986418049732\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672824 with a delay 1200000000, Now = 211419424\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9168 with delay 1200000\nI 28.621s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947174152 with a delay 0, Now = 211419424\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90d0 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [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 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9178 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947174152 with a delay 10000000, Now = 211419424\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9170 with delay 10000\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9178\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f9178 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7f740f9178\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1959253480 with a delay 500000, Now = 211469424\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f90d0 with delay 500\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1959253576 with a delay 60000000, Now = 211469424\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f9158 with delay 60000\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7f740f90d0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [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 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7f740f9170\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7f740f9160\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7f740f9158\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [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 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [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 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1959253480 with a delay 500000, Now = 271469424\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7f740f9160 with delay 500\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253576 with a delay 60000000, Now = 271469424\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7f740f9170 with delay 60000\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7f740f9160\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [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 28.622s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.NetworkTimeouts (12 ms)\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90d8\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9160\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9160\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253864 with a delay 0, Now = 210919424\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9180 with delay 0\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9180\nI 28.622s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4964823606959339567\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253672 with a delay 500000, Now = 210919424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 500\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253864 with a delay 60000000, Now = 210919424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9178 with delay 60000\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9160\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [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: \"4964823606959339567\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9160 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9160\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4964823606959339567\" 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 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4964823606959339567\"\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672488 with a delay 1200000000, Now = 211419424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9180 with delay 1200000\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947174152 with a delay 0, Now = 211419424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [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 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d8\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9190 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947174152 with a delay 10000000, Now = 211419424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9188 with delay 10000\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9190\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7f740f9190 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7f740f9190\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [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 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7f740f9188\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [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 28.623s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.NoRegistrationSummary (9 ms)\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [ RUN ] InvalidationClientImplTest.Heartbeats\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90d8\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9160\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9170\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: \nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9160\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(351)] Starting with no previous state\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253288 with a delay 0, Now = 210919424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9170 with delay 0\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9170\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1864665375886103110\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1959253864 with a delay 500000, Now = 210919424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9160 with delay 500\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1959253288 with a delay 60000000, Now = 210919424\nI 28.623s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9168 with delay 60000\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9160\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"\"\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [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: \"1864665375886103110\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9160 with delay 0\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9160\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1864665375886103110\" 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 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1864665375886103110\"\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2127672488 with a delay 1200000000, Now = 211419424\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9170 with delay 1200000\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1947174152 with a delay 0, Now = 211419424\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f90d8 with delay 0\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [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 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d8\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9190 with delay 0\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1947174152 with a delay 10000000, Now = 211419424\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7f740f9188 with delay 10000\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9190\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, \nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7f740f9188\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7f740f9168\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7f740f9170\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [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 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1959253864 with a delay 500000, Now = 1411419424\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7f740f9168 with delay 500\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling 2127672488 with a delay 1200000000, Now = 1411419424\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7f740f9188 with delay 1200000\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7f740f9168\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [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 28.624s run_tests_on_device(01e2ea64a25dba85) [ OK ] InvalidationClientImplTest.Heartbeats (16 ms)\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [----------] 10 tests from InvalidationClientImplTest (121 ms total)\nI 28.624s run_tests_on_device(01e2ea64a25dba85) \nI 28.624s run_tests_on_device(01e2ea64a25dba85) [----------] 13 tests from ProtocolHandlerTest\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.SendInitializeOnly\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9070 with delay 0\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9070\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [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 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1959253384 with a delay 500000, Now = 210919424\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90a8 with delay 500\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90a8\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [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 28.624s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.SendInitializeOnly (4 ms)\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\nI 28.624s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (2 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9090 with delay 0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9098 with delay 0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90a0 with delay 0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90a8 with delay 0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90b0 with delay 0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90b8 with delay 0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9090\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1959253192 with a delay 500000, Now = 210919424\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f90d8 with delay 500\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9098\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90a0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90a8\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90b0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f90b8\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f90d8\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (6 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (2 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.InvalidInboundMessage (2 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.MajorVersionMismatch (2 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.MinorVersionMismatch (2 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.ConfigMessage\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9090 with delay 0\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9090\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1959253480 with a delay 500000, Now = 210919424\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9098 with delay 500\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9098\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.ConfigMessage (10 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.ErrorMessage\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.ErrorMessage (2 ms)\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.TokenMismatch\nI 28.625s run_tests_on_device(01e2ea64a25dba85) [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 28.625s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms)\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.TokenMissing\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9090 with delay 0\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9090\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [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 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1959253864 with a delay 500000, Now = 210919424\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9098 with delay 500\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9098\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [WARNING:protocol-handler.cc(313)] Unable to build message\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9090 with delay 0\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7f740f9090\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1959253480 with a delay 500000, Now = 210919424\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7f740f9098 with delay 500\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7f740f9098\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [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 28.626s run_tests_on_device(01e2ea64a25dba85) [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 28.626s run_tests_on_device(01e2ea64a25dba85) [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 28.626s run_tests_on_device(01e2ea64a25dba85) [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 28.626s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:protocol-handler.cc(139)] Incoming message: { }\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ERROR:ticl-message-validator.cc(361)] required field header missing from { }\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ERROR:protocol-handler.cc(145)] Received invalid message: { }\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [----------] 13 tests from ProtocolHandlerTest (42 ms total)\nI 28.626s run_tests_on_device(01e2ea64a25dba85) \nI 28.626s run_tests_on_device(01e2ea64a25dba85) [----------] 3 tests from RecurringTaskTest\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [ RUN ] RecurringTaskTest.PeriodicTask\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -819811768 with a delay 10000, Now = 0\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7f740f9030 with delay 10\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7f740f9030\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (10000) Task running: 1\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 60000, Now = 10000\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7f740f9038 with delay 60\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7f740f9038\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (70000) Task running: 2\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 60000, Now = 70000\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7f740f9030 with delay 60\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7f740f9030\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (130000) Task running: 3\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 60000, Now = 130000\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7f740f9038 with delay 60\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7f740f9038\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (190000) Task running: 4\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 60000, Now = 190000\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7f740f9030 with delay 60\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7f740f9030\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (250000) Task running: 5\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 60000, Now = 250000\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7f740f9038 with delay 60\nI 28.626s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7f740f9038\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (310000) Task running: 6\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 60000, Now = 310000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7f740f9030 with delay 60\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7f740f9030\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (370000) Task running: 7\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 60000, Now = 370000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7f740f9038 with delay 60\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7f740f9038\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (430000) Task running: 8\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [ OK ] RecurringTaskTest.PeriodicTask (6 ms)\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [ RUN ] RecurringTaskTest.ExponentialBackoffTask\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -819811768 with a delay 10000, Now = 0\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7f740f9038 with delay 10\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7f740f9038\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (10000) Task running: 1\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 50000, Now = 10000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7f740f9030 with delay 50\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7f740f9030\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (60000) Task running: 2\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 149000, Now = 60000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7f740f9038 with delay 149\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7f740f9038\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (210000) Task running: 3\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 248000, Now = 210000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7f740f9030 with delay 248\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7f740f9030\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (460000) Task running: 4\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 446000, Now = 460000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7f740f9038 with delay 446\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7f740f9038\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (910000) Task running: 5\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 842000, Now = 910000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7f740f9030 with delay 842\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7f740f9030\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 1040000, Now = 1760000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7f740f9038 with delay 1040\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7f740f9038\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [Retry] Scheduling -819811768 with a delay 1040000, Now = 2800000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7f740f9030 with delay 1040\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7f740f9030\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [ OK ] RecurringTaskTest.ExponentialBackoffTask (5 ms)\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [ RUN ] RecurringTaskTest.OneShotTask\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -819811784 with a delay 10000, Now = 0\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7f740f9030 with delay 10\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7f740f9030\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (10000) Task running: 1\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -819811784 with a delay 10000, Now = 10000\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7f740f9030 with delay 10\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7f740f9030\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [INFO:recurring-task_test.cc(71)] (20000) Task running: 2\nI 28.627s run_tests_on_device(01e2ea64a25dba85) [ OK ] RecurringTaskTest.OneShotTask (3 ms)\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [----------] 3 tests from RecurringTaskTest (15 ms total)\nI 28.628s run_tests_on_device(01e2ea64a25dba85) \nI 28.628s run_tests_on_device(01e2ea64a25dba85) [----------] 2 tests from ThrottleTest\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ThrottleTest.ThrottlingScripted\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7f740f9050 with delay 920\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7f740f9050 with delay 45000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [ OK ] ThrottleTest.ThrottlingScripted (2 ms)\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [ RUN ] ThrottleTest.ThrottlingStorm\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7f740f9050 with delay 990\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7f740f9058 with delay 54000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7f740f9050 with delay 54000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7f740f9050\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7f740f9058 with delay 54000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7f740f9058\nI 28.628s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7f740f9058\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7f740f9058\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7f740f9058\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7f740f9058\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7f740f9058 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7f740f9058\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7f740f9050 with delay 54000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7f740f9050\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7f740f9050\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7f740f9050\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7f740f9050\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7f740f9050\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7f740f9050\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7f740f9050 with delay 1000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7f740f9050\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7f740f9058 with delay 54000\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7f740f9058\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [ OK ] ThrottleTest.ThrottlingStorm (15 ms)\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [----------] 2 tests from ThrottleTest (17 ms total)\nI 28.629s run_tests_on_device(01e2ea64a25dba85) \nI 28.629s run_tests_on_device(01e2ea64a25dba85) [----------] Global test environment tear-down\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [==========] 28 tests from 4 test suites ran. (198 ms total)\nI 28.629s run_tests_on_device(01e2ea64a25dba85) [ PASSED ] 28 tests.\nI 28.629s run_tests_on_device(01e2ea64a25dba85) <<ScopedMainEntryLogger\nI 28.631s run_tests_on_device(01e2ea64a25dba85) Finished running tests on this device.\nI 28.634s Main FINISHED TRY #1/3\nI 28.634s Main All tests completed.\nC 28.634s Main ********************************************************************************\nC 28.634s Main Summary\nC 28.634s Main ********************************************************************************\nC 28.634s Main [==========] 28 tests ran.\nC 28.634s Main [ PASSED ] 28 tests.\nC 28.634s Main ********************************************************************************\nI 28.635s tear_down_device(01e2ea64a25dba85) Wrote device cache: /b/swarming/w/ir/out/Release/device_cache_01e2ea64a25dba85.json\nI 28.636s Main Generated json results file at /b/swarming/w/ituyymz9/tmpnSecip\nI 28.637s Main Finishing archiving output.\n[W2019-01-23T04:31:26.436502Z 29042 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-01-23T04:31:26.538446Z 29042 0 main.go:205] Butler terminated with error. {\"error\":\"context canceled\"}\n[E2019-01-23T04:31:26.538471Z 29042 0 main.go:233] Failed to serve.\noriginal error: context canceled\n\n[I2019-01-23T04:31:26.538508Z 29042 0 main.go:349] Terminating. {\"returnCode\":250}\nINFO:devil.utils.timeout_retry:condition 'logdog_stopped' met\n", "outputs_ref": { "isolated": "8f63755a3d11b7b2a1e225b0a4b157cccbb88d39", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "4291cb09ca594111", "server_versions": [ "4016-2f4b7db" ], "started_ts": "2019-01-23T04:30:44.529483", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:android-marshmallow-arm64-rel", "buildnumber:12089", "data:d733a03adf183cf573eb6931e2be576bb9bbb583", "device_os:MMB29Q", "device_type:bullhead", "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:swarm1596-c4", "spec_name:chromium.ci:android-marshmallow-arm64-rel", "stepname:cacheinvalidation_unittests on Android device Nexus 5X", "swarming.pool.template:none", "swarming.pool.version:bfaf050e23eebcbcbc1d0bdaeed45d147a95e5e4", "user:None" ], "task_id": "4292fed21ecaf310" } ] }