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

{ "shards": [ { "bot_dimensions": [ { "key": "caches", "value": [ "swarming_module_cache_vpython" ] }, { "key": "cores", "value": [ "8" ] }, { "key": "cpu", "value": [ "x86", "x86-64", "x86-64-Broadwell_GCE", "x86-64-avx2" ] }, { "key": "gce", "value": [ "1" ] }, { "key": "gpu", "value": [ "none" ] }, { "key": "id", "value": [ "chrome-trusty-us-east1-b-2-witx" ] }, { "key": "image", "value": [ "chrome-trusty-19041600-95c8804d634" ] }, { "key": "inside_docker", "value": [ "0" ] }, { "key": "kvm", "value": [ "1" ] }, { "key": "machine_type", "value": [ "n1-standard-8" ] }, { "key": "os", "value": [ "Linux", "Ubuntu", "Ubuntu-14.04" ] }, { "key": "pool", "value": [ "Chrome" ] }, { "key": "python", "value": [ "2.7.6" ] }, { "key": "server_version", "value": [ "4274-a0a5f8c" ] }, { "key": "zone", "value": [ "us", "us-east", "us-east1", "us-east1-b" ] } ], "bot_id": "chrome-trusty-us-east1-b-2-witx", "bot_version": "ed4565f416d57730e75be543776f9c0eb206896ef8831a69fda252ac9fa2095a", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "nFftZl2kFquaI2EUmPGwzbc5sIbCocl9L55UeASqlLsC" }, "packages": [ { "package_name": "infra/python/cpython/linux-amd64", "path": ".swarming_module", "version": "46c0c897ca0f053799ee41fd148bb7a47232df47" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": ".swarming_module", "version": "2737ea8ed9b958f4d5aa9ffe106115a649ada241" }, { "package_name": "infra/tools/luci/vpython-native/linux-amd64", "path": ".swarming_module", "version": "tfTmX4aGCfFtfQucj_nEfwiNisK0RmpKrITkZMBBq3cC" }, { "package_name": "infra/tools/luci/vpython/linux-amd64", "path": ".swarming_module", "version": "bmnYyAg9mbM_538s1dIP1hZZmOtc8C7ssF41ztN2cr0C" } ] }, "completed_ts": "2019-04-24T21:45:50.384643", "costs_usd": [ 0.0016876605932212682 ], "created_ts": "2019-04-24T21:45:26.182491", "duration": 0.8870182037353516, "modified_ts": "2019-04-24T21:45:50.384643", "name": "cacheinvalidation_unittests (with patch)/Ubuntu-14.04/70ccc297f3/linux_chromium_msan_rel_ng/1438", "output": "/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:354: SNIMissingWarning: An HTTPS request has been made, but the SNI (Server Name Indication) extension to TLS is not available on this platform. This may cause the server to present an incorrect TLS certificate, which can cause validation failures. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\n/b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings\nAdditional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n MSAN_OPTIONS=symbolize=0 handle_abort=1\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioqHv1Lk/output.json\n\nIMPORTANT DEBUGGING NOTE: batches of tests are run inside their\nown process. For debugging a test inside a debugger, use the\n--gtest_filter=<your_test_name> flag along with\n--single-process-tests.\nUsing sharding settings from environment. This is shard 0/1\nUsing 8 parallel jobs.\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[11649:11649:0424/144549.221982:1081626634:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b60 with delay 0\n[11649:11649:0424/144549.222697:1081627336:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b60\n[11649:11649:0424/144549.223141:1081627792: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 }\n[11649:11649:0424/144549.223291:1081627951:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424\n[11649:11649:0424/144549.223443:1081628090:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000bf0 with delay 500\n[11649:11649:0424/144549.223574:1081628211:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000bf0\n[11649:11649:0424/144549.224091:1081628734: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 } }\n[ OK ] ProtocolHandlerTest.SendInitializeOnly (5 ms)\n[1/28] ProtocolHandlerTest.SendInitializeOnly (5 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[11649:11649:0424/144549.226003:1081630648: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\" } }\n[ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[11649:11649:0424/144549.226754:1081631402:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[11649:11649:0424/144549.226944:1081631588:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b20 with delay 0\n[11649:11649:0424/144549.227071:1081631715:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000aa0 with delay 0\n[11649:11649:0424/144549.227208:1081631849:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0\n[11649:11649:0424/144549.227295:1081631910:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a90 with delay 0\n[11649:11649:0424/144549.227367:1081632026:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0\n[11649:11649:0424/144549.228162:1081632805:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[11649:11649:0424/144549.228397:1081633027: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 }\n[11649:11649:0424/144549.228488:1081633124:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424\n[11649:11649:0424/144549.228570:1081633208:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c40 with delay 500\n[11649:11649:0424/144549.228644:1081633259:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b20\n[11649:11649:0424/144549.228695:1081633310:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000aa0\n[11649:11649:0424/144549.228733:1081633348:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0\n[11649:11649:0424/144549.228778:1081633393:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a90\n[11649:11649:0424/144549.228815:1081633435:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0\n[11649:11649:0424/144549.228893:1081633537:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[11649:11649:0424/144549.229009:1081633645:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c40\n[11649:11649:0424/144549.229325:1081633977:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[11649:11649:0424/144549.229895:1081634543: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 } }\n[ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms)\n[3/28] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[11649:11649:0424/144549.232303:1081636955: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 } }\n[ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[4/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[11649:11649:0424/144549.233161:1081637787: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 } }\n[11649:11649:0424/144549.233308:1081637957: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\" }\n[11649:11649:0424/144549.233454:1081638092: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 } }\n[11649:11649:0424/144549.233629:1081638267: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 } }\n[ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[5/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[11649:11649:0424/144549.234263:1081638893: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 } }\n[11649:11649:0424/144549.234425:1081639058: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 } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[6/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[11649:11649:0424/144549.235009:1081639652: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\" } }\n[ OK ] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[7/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[11649:11649:0424/144549.235645:1081640284: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\" } }\n[11649:11649:0424/144549.235755:1081640394:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a20 with delay 0\n[11649:11649:0424/144549.235839:1081640475:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a20\n[11649:11649:0424/144549.235987:1081640618: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 }\n[11649:11649:0424/144549.236071:1081640705:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424\n[11649:11649:0424/144549.236138:1081640773:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a30 with delay 500\n[11649:11649:0424/144549.236223:1081640865:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a30\n[11649:11649:0424/144549.236308:1081640963:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (46 ms)\n[8/28] ProtocolHandlerTest.ConfigMessage (46 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[11649:11649:0424/144549.281591:1081686230: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\" } }\n[ OK ] ProtocolHandlerTest.ErrorMessage (0 ms)\n[9/28] ProtocolHandlerTest.ErrorMessage (0 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[11649:11649:0424/144549.282232:1081686868: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\" } }\n[ OK ] ProtocolHandlerTest.TokenMismatch (1 ms)\n[10/28] ProtocolHandlerTest.TokenMismatch (1 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[11647:11647:0424/144549.184857:1081589502:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c60 with delay 0\n[11647:11647:0424/144549.185379:1081590030:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.186239:1081590886:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0\n[11647:11647:0424/144549.186356:1081591005:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c60\n[11647:11647:0424/144549.186471:1081591086:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30\n[11647:11647:0424/144549.186650:1081591296:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.186866:1081591511:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0\n[11647:11647:0424/144549.186990:1081591605:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80\n[11647:11647:0424/144549.187038:1081591686:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.187138:1081591780:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0\n[11647:11647:0424/144549.187236:1081591851:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30\n[11647:11647:0424/144549.187293:1081591951:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.187434:1081592079:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.187549:1081592202:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0\n[11647:11647:0424/144549.187653:1081592268:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80\n[11647:11647:0424/144549.187804:1081592458:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1719975034639202606\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.187921:1081592562:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.188016:1081592656:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 500\n[11647:11647:0424/144549.188122:1081592753:INFO:recurring-task.cc(55)] [Retry] Scheduling 9224 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.188209:1081592855:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000df0 with delay 60000\n[11647:11647:0424/144549.188320:1081592982:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e30\n[11647:11647:0424/144549.188443:1081593089:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.188610:1081593253:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.188927:1081593571: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: \"-1719975034639202606\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.189394:1081594039:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e30 with delay 0\n[11647:11647:0424/144549.189512:1081594160:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e30\n[11647:11647:0424/144549.189832:1081594473:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1719975034639202606\" 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\" } }\n[11647:11647:0424/144549.189988:1081594628:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1719975034639202606\"\n[11647:11647:0424/144549.190088:1081594730:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.190193:1081594834:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.190294:1081594951:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e70 with delay 1200000\n[11647:11647:0424/144549.190418:1081595066:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.190809:1081595445:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.190907:1081595547:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.191001:1081595638:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e80 with delay 0\n[11647:11647:0424/144549.191132:1081595774: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\n[11647:11647:0424/144549.191235:1081595851:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e80\n[11647:11647:0424/144549.191488:1081596135:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ea0 with delay 0\n[11647:11647:0424/144549.191602:1081596232:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.191683:1081596319:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c60 with delay 10000\n[11647:11647:0424/144549.191765:1081596381:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ea0\n[11647:11647:0424/144549.191809:1081596448:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (10 ms)\n[11/28] InvalidationClientImplTest.Start (10 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[11647:11647:0424/144549.193080:1081597698:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[11647:11647:0424/144549.193150:1081597767:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)\n[12/28] InvalidationClientImplTest.GenerateNonce (1 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[11647:11647:0424/144549.193881:1081598498:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e60 with delay 0\n[11647:11647:0424/144549.193945:1081598560:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.194593:1081599233:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ec0 with delay 0\n[11647:11647:0424/144549.194682:1081599322:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e60\n[11647:11647:0424/144549.194751:1081599366:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ec0\n[11647:11647:0424/144549.194837:1081599473:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.194948:1081599565:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0\n[11647:11647:0424/144549.195008:1081599624:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00\n[11647:11647:0424/144549.195050:1081599688:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.195136:1081599776:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ec0 with delay 0\n[11647:11647:0424/144549.195204:1081599820:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ec0\n[11647:11647:0424/144549.195247:1081599884:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.195327:1081599986:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.195456:1081600100:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0\n[11647:11647:0424/144549.195538:1081600153:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00\n[11647:11647:0424/144549.195655:1081600288:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1824600431616051415\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.195729:1081600375:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9224 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.195815:1081600454:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ec0 with delay 500\n[11647:11647:0424/144549.195900:1081600540:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.195987:1081600625:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 60000\n[11647:11647:0424/144549.196087:1081600725:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0\n[11647:11647:0424/144549.196166:1081600812:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.196269:1081600909:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.196498:1081601145: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: \"-1824600431616051415\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.196753:1081601385:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 0\n[11647:11647:0424/144549.196834:1081601470:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0\n[11647:11647:0424/144549.197066:1081601703:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1824600431616051415\" 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\" } }\n[11647:11647:0424/144549.197183:1081601817:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1824600431616051415\"\n[11647:11647:0424/144549.197249:1081601889:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.197321:1081601972:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.197419:1081602055:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ef0 with delay 1200000\n[11647:11647:0424/144549.197505:1081602138:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.197699:1081602339:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.197794:1081602428:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.197857:1081602491:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f00 with delay 0\n[11647:11647:0424/144549.197949:1081602579: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\n[11647:11647:0424/144549.198034:1081602649:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f00\n[11647:11647:0424/144549.198139:1081602756:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[11647:11647:0424/144549.198205:1081602840:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.198276:1081602911:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e60 with delay 10000\n[11647:11647:0424/144549.198349:1081602965:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[11647:11647:0424/144549.198392:1081603028:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.198565:1081603197:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 0\n[11647:11647:0424/144549.198643:1081603279:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f20\n[11647:11647:0424/144549.198789:1081603433:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[11647:11647:0424/144549.198871:1081603487:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[11647:11647:0424/144549.198917:1081603532:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[11647:11647:0424/144549.199010:1081603649:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9224 with a delay 500000, Now = 211469424\n[11647:11647:0424/144549.199097:1081603738:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f00 with delay 500\n[11647:11647:0424/144549.199181:1081603812:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424\n[11647:11647:0424/144549.199250:1081603886:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f10 with delay 60000\n[11647:11647:0424/144549.199372:1081604045:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f00\n[11647:11647:0424/144549.199492:1081604123:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.199601:1081604238:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.199671:1081604315:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[11647:11647:0424/144549.199969:1081604613: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 } } }\n[11647:11647:0424/144549.200170:1081604802:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.200362:1081605000:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f00 with delay 0\n[11647:11647:0424/144549.200450:1081605082:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f00\n[11647:11647:0424/144549.200775:1081605410: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 } } } }\n[11647:11647:0424/144549.200942:1081605580: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\n[11647:11647:0424/144549.201066:1081605703:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[11647:11647:0424/144549.201250:1081605866:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[11647:11647:0424/144549.201362:1081605977:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[11647:11647:0424/144549.201696:1081606330:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e60\n[ OK ] InvalidationClientImplTest.Register (10 ms)\n[13/28] InvalidationClientImplTest.Register (10 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[11647:11647:0424/144549.203645:1081608264:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000da0 with delay 0\n[11647:11647:0424/144549.203716:1081608333:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.204373:1081609004:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 0\n[11647:11647:0424/144549.204454:1081609094:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000da0\n[11647:11647:0424/144549.204532:1081609147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c10\n[11647:11647:0424/144549.204619:1081609250:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.204728:1081609345:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[11647:11647:0424/144549.204781:1081609396:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[11647:11647:0424/144549.204816:1081609443:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.204880:1081609511:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 0\n[11647:11647:0424/144549.204950:1081609565:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c10\n[11647:11647:0424/144549.204990:1081609612:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.205066:1081609704:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.205142:1081609790:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[11647:11647:0424/144549.205228:1081609843:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[11647:11647:0424/144549.205313:1081609955:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8998233903840132195\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.205397:1081610032:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.205462:1081610083:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 500\n[11647:11647:0424/144549.205519:1081610159:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.205610:1081610243:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 60000\n[11647:11647:0424/144549.205691:1081610323:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10\n[11647:11647:0424/144549.205756:1081610385:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.205831:1081610456:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.205993:1081610634: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: \"8998233903840132195\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.206173:1081610807:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c10 with delay 0\n[11647:11647:0424/144549.206264:1081610891:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10\n[11647:11647:0424/144549.206480:1081611116:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8998233903840132195\" 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\" } }\n[11647:11647:0424/144549.206570:1081611198:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8998233903840132195\"\n[11647:11647:0424/144549.206633:1081611266:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.206708:1081611350:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.206782:1081611414:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 1200000\n[11647:11647:0424/144549.206853:1081611484:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.207041:1081611675:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.207106:1081611744:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.207181:1081611808:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[11647:11647:0424/144549.207266:1081611893: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\n[11647:11647:0424/144549.207333:1081611958:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[11647:11647:0424/144549.207439:1081612056:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f50 with delay 0\n[11647:11647:0424/144549.207502:1081612133:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.207568:1081612205:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000da0 with delay 10000\n[11647:11647:0424/144549.207642:1081612258:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f50\n[11647:11647:0424/144549.207682:1081612322:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.207782:1081612415:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.207879:1081612506:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 0\n[11647:11647:0424/144549.207948:1081612583:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f50\n[11647:11647:0424/144549.208227:1081612855: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 } } }\n[11647:11647:0424/144549.208366:1081612988: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\n[11647:11647:0424/144549.208475:1081613106: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\" }\n[11647:11647:0424/144549.208675:1081613291:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true }\n[11647:11647:0424/144549.208772:1081613387:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true }\n[11647:11647:0424/144549.208867:1081613502:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f50 with delay 0\n[11647:11647:0424/144549.208939:1081613566:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f20 with delay 0\n[11647:11647:0424/144549.209001:1081613625:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f30 with delay 0\n[11647:11647:0424/144549.209060:1081613688:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f50\n[11647:11647:0424/144549.209147:1081613785:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424\n[11647:11647:0424/144549.209217:1081613847:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000c10 with delay 500\n[11647:11647:0424/144549.209292:1081613907:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f20\n[11647:11647:0424/144549.209346:1081613960:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f30\n[11647:11647:0424/144549.209405:1081614039:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000000c10\n[11647:11647:0424/144549.209469:1081614099:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.209553:1081614193:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.209617:1081614249:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[11647:11647:0424/144549.209850:1081614485: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 } } }\n[ OK ] InvalidationClientImplTest.Invalidations (7 ms)\n[14/28] InvalidationClientImplTest.Invalidations (7 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[11647:11647:0424/144549.211042:1081615671:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e90 with delay 0\n[11647:11647:0424/144549.211120:1081615737:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.211427:1081616050:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0\n[11647:11647:0424/144549.211496:1081616123:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e90\n[11647:11647:0424/144549.211550:1081616170:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0\n[11647:11647:0424/144549.211627:1081616257:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.211716:1081616333:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0\n[11647:11647:0424/144549.211763:1081616378:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00\n[11647:11647:0424/144549.211802:1081616436:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.211867:1081616500:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0\n[11647:11647:0424/144549.211928:1081616544:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0\n[11647:11647:0424/144549.211968:1081616599:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.212032:1081616663:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.212100:1081616732:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0\n[11647:11647:0424/144549.212159:1081616774:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00\n[11647:11647:0424/144549.212236:1081616871:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3619508849409224037\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.212310:1081616957:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.212393:1081617016:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 500\n[11647:11647:0424/144549.212440:1081617064:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.212496:1081617123:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d20 with delay 60000\n[11647:11647:0424/144549.212574:1081617199:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0\n[11647:11647:0424/144549.212631:1081617262:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.212704:1081617326:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.212865:1081617487: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: \"3619508849409224037\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.213025:1081617654:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000cf0 with delay 0\n[11647:11647:0424/144549.213102:1081617729:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0\n[11647:11647:0424/144549.213250:1081617880:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3619508849409224037\" 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\" } }\n[11647:11647:0424/144549.213323:1081617954:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3619508849409224037\"\n[11647:11647:0424/144549.213383:1081618004:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.213441:1081618071:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.213498:1081618124:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000be0 with delay 1200000\n[11647:11647:0424/144549.213566:1081618196:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.213740:1081618356:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.213795:1081618411:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.213842:1081618473:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f00 with delay 0\n[11647:11647:0424/144549.213928:1081618563: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\n[11647:11647:0424/144549.214003:1081618618:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f00\n[11647:11647:0424/144549.214086:1081618701:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 0\n[11647:11647:0424/144549.214137:1081618768:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.214200:1081618831:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e90 with delay 10000\n[11647:11647:0424/144549.214258:1081618874:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c00\n[11647:11647:0424/144549.214299:1081618924:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.214385:1081619006:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.214454:1081619079:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000c00 with delay 0\n[11647:11647:0424/144549.214509:1081619136:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000c00\n[11647:11647:0424/144549.214677:1081619313: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 } }\n[11647:11647:0424/144549.214791:1081619430: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\n[11647:11647:0424/144549.214871:1081619507:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[11647:11647:0424/144549.214940:1081619575:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424\n[11647:11647:0424/144549.215005:1081619628:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f00 with delay 500\n[11647:11647:0424/144549.215071:1081619706:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[11647:11647:0424/144549.215423:1081620060: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 }\n[11647:11647:0424/144549.215530:1081620152:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f00\n[11647:11647:0424/144549.215597:1081620224:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.215697:1081620326:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.215756:1081620377:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[11647:11647:0424/144549.216136:1081620768: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 } }\n[11647:11647:0424/144549.216505:1081621121:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e90\n[ OK ] InvalidationClientImplTest.ServerRequests (7 ms)\n[15/28] InvalidationClientImplTest.ServerRequests (7 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[11647:11647:0424/144549.218130:1081622749:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 0\n[11647:11647:0424/144549.218203:1081622819:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.218512:1081623130:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0\n[11647:11647:0424/144549.218572:1081623205:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b30\n[11647:11647:0424/144549.218639:1081623254:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0\n[11647:11647:0424/144549.218709:1081623343:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.218792:1081623408:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0\n[11647:11647:0424/144549.218836:1081623452:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0\n[11647:11647:0424/144549.218882:1081623509:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.218932:1081623572:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0\n[11647:11647:0424/144549.219000:1081623615:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0\n[11647:11647:0424/144549.219035:1081623674:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.219107:1081623743:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.219181:1081623803:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0\n[11647:11647:0424/144549.219238:1081623853:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0\n[11647:11647:0424/144549.219316:1081623953:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3025908773678410903\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.219390:1081624044:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.219477:1081624108:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 500\n[11647:11647:0424/144549.219542:1081624177:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.219607:1081624239:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ab0 with delay 60000\n[11647:11647:0424/144549.219675:1081624315:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0\n[11647:11647:0424/144549.219750:1081624382:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.219824:1081624455:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.219982:1081624607: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: \"-3025908773678410903\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.220127:1081624761:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000cf0 with delay 0\n[11647:11647:0424/144549.220187:1081624821:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0\n[11647:11647:0424/144549.220353:1081624987:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3025908773678410903\" 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\" } }\n[11647:11647:0424/144549.220442:1081625068:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3025908773678410903\"\n[11647:11647:0424/144549.220508:1081625130:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.220572:1081625203:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.220630:1081625258:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 1200000\n[11647:11647:0424/144549.220692:1081625326:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.220844:1081625475:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.220912:1081625539:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.220970:1081625592:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ac0 with delay 0\n[11647:11647:0424/144549.221046:1081625674: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\n[11647:11647:0424/144549.221116:1081625732:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ac0\n[11647:11647:0424/144549.221189:1081625804:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000009c0 with delay 0\n[11647:11647:0424/144549.221237:1081625869:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.221297:1081625921:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 10000\n[11647:11647:0424/144549.221360:1081625975:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000009c0\n[11647:11647:0424/144549.221399:1081626024:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.221479:1081626110:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.221563:1081626189:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000009c0 with delay 0\n[11647:11647:0424/144549.221629:1081626255:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000009c0\n[11647:11647:0424/144549.221769:1081626395: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\" } }\n[11647:11647:0424/144549.221858:1081626484: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\n[11647:11647:0424/144549.221919:1081626552:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[11647:11647:0424/144549.222298:1081626949:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000b30\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (6 ms)\n[16/28] InvalidationClientImplTest.IncomingErrorMessage (6 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[11647:11647:0424/144549.223938:1081628556:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d70 with delay 0\n[11647:11647:0424/144549.224006:1081628622:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.224401:1081629029:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[11647:11647:0424/144549.224469:1081629096:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d70\n[11647:11647:0424/144549.224521:1081629136:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[11647:11647:0424/144549.224662:1081629294:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.224749:1081629365:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f30 with delay 0\n[11647:11647:0424/144549.224799:1081629414:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f30\n[11647:11647:0424/144549.224834:1081629451:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.224877:1081629499:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[11647:11647:0424/144549.224929:1081629544:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[11647:11647:0424/144549.224963:1081629588:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.225020:1081629646:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.225071:1081629707:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f30 with delay 0\n[11647:11647:0424/144549.225130:1081629746:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f30\n[11647:11647:0424/144549.225203:1081629839:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3687373145500740882\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.225275:1081629902:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.225328:1081629973:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 500\n[11647:11647:0424/144549.225409:1081630031:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.225463:1081630080:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 60000\n[11647:11647:0424/144549.225520:1081630151:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[11647:11647:0424/144549.225581:1081630216:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.225655:1081630283:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.225807:1081630429: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: \"3687373145500740882\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.225949:1081630571:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e50 with delay 0\n[11647:11647:0424/144549.226005:1081630622:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[11647:11647:0424/144549.226152:1081630784:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3687373145500740882\" 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\" } }\n[11647:11647:0424/144549.226241:1081630881:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3687373145500740882\"\n[11647:11647:0424/144549.226306:1081630948:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.226383:1081631012:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.226446:1081631078:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 1200000\n[11647:11647:0424/144549.226512:1081631150:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.226687:1081631313:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.226740:1081631371:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.226794:1081631425:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f30 with delay 0\n[11647:11647:0424/144549.226871:1081631497: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\n[11647:11647:0424/144549.226933:1081631548:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f30\n[11647:11647:0424/144549.227009:1081631624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0\n[11647:11647:0424/144549.227065:1081631687:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.227113:1081631740:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d70 with delay 10000\n[11647:11647:0424/144549.227175:1081631790:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40\n[11647:11647:0424/144549.227209:1081631836:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.227284:1081631909:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f40 with delay 0\n[11647:11647:0424/144549.227352:1081631974:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f40\n[11647:11647:0424/144549.227442:1081632074:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[11647:11647:0424/144549.227531:1081632153:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424\n[11647:11647:0424/144549.227591:1081632218:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f30 with delay 500\n[11647:11647:0424/144549.227654:1081632291:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9224 with a delay 60000000, Now = 211469424\n[11647:11647:0424/144549.227719:1081632340:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 60000\n[11647:11647:0424/144549.227791:1081632424:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f30\n[11647:11647:0424/144549.227856:1081632480:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.227920:1081632550:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.227980:1081632605:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[11647:11647:0424/144549.228136:1081632770: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 } } }\n[11647:11647:0424/144549.228275:1081632902:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.228359:1081632997:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f30 with delay 0\n[11647:11647:0424/144549.228432:1081633053:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f30\n[11647:11647:0424/144549.228569:1081633192: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\" } }\n[11647:11647:0424/144549.228657:1081633279: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\n[11647:11647:0424/144549.228714:1081633331:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[11647:11647:0424/144549.228821:1081633451:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[11647:11647:0424/144549.229168:1081633791:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000d70\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (7 ms)\n[17/28] InvalidationClientImplTest.IncomingAuthErrorMessage (7 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[11647:11647:0424/144549.230787:1081635405:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c00 with delay 0\n[11647:11647:0424/144549.230853:1081635469:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.231124:1081635747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 0\n[11647:11647:0424/144549.231179:1081635796:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c00\n[11647:11647:0424/144549.231218:1081635833:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b30\n[11647:11647:0424/144549.231292:1081635921:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.231390:1081636020:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e00 with delay 0\n[11647:11647:0424/144549.231457:1081636072:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e00\n[11647:11647:0424/144549.231498:1081636125:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.231557:1081636189:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 0\n[11647:11647:0424/144549.231616:1081636231:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b30\n[11647:11647:0424/144549.231651:1081636273:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.231716:1081636342:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.231775:1081636397:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e00 with delay 0\n[11647:11647:0424/144549.231822:1081636437:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e00\n[11647:11647:0424/144549.231901:1081636521:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-8515786912500830722\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.231954:1081636571:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.231997:1081636623:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 500\n[11647:11647:0424/144549.232055:1081636683:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.232110:1081636740:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 60000\n[11647:11647:0424/144549.232188:1081636805:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b30\n[11647:11647:0424/144549.232234:1081636867:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.232313:1081636953:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.232481:1081637108: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: \"-8515786912500830722\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.232628:1081637255:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 0\n[11647:11647:0424/144549.232684:1081637311:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b30\n[11647:11647:0424/144549.232844:1081637470:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-8515786912500830722\" 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\" } }\n[11647:11647:0424/144549.232919:1081637550:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-8515786912500830722\"\n[11647:11647:0424/144549.232979:1081637606:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.233033:1081637668:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.233093:1081637732:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 1200000\n[11647:11647:0424/144549.233159:1081637792:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.233321:1081637951:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.233388:1081638010:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.233434:1081638066:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e00 with delay 0\n[11647:11647:0424/144549.233519:1081638136: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\n[11647:11647:0424/144549.233580:1081638196:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e00\n[11647:11647:0424/144549.233665:1081638281:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a30 with delay 0\n[11647:11647:0424/144549.233717:1081638351:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.233783:1081638405:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 10000\n[11647:11647:0424/144549.233837:1081638452:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a30\n[11647:11647:0424/144549.233871:1081638493:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.233941:1081638562:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a30 with delay 0\n[11647:11647:0424/144549.233987:1081638619:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a30\n[11647:11647:0424/144549.234070:1081638696:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[11647:11647:0424/144549.234148:1081638775:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424\n[11647:11647:0424/144549.234211:1081638838:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000e00 with delay 500\n[11647:11647:0424/144549.234268:1081638885:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424\n[11647:11647:0424/144549.234312:1081638957:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000ad0 with delay 60000\n[11647:11647:0424/144549.234402:1081639031:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000e00\n[11647:11647:0424/144549.234460:1081639088:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.234529:1081639156:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.234595:1081639220:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[11647:11647:0424/144549.234750:1081639380: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 } } }\n[11647:11647:0424/144549.235097:1081639727:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c00\n[11647:11647:0424/144549.236313:1081640928:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000c30\n[11647:11647:0424/144549.236372:1081640986:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000ad0\n[11647:11647:0424/144549.236438:1081641069: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\n[11647:11647:0424/144549.236498:1081641125:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[11647:11647:0424/144549.236614:1081641236: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 }\n[11647:11647:0424/144549.236674:1081641299:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424\n[11647:11647:0424/144549.236726:1081641344:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c30 with delay 500\n[11647:11647:0424/144549.236767:1081641391:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424\n[11647:11647:0424/144549.236814:1081641444:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c00 with delay 60000\n[11647:11647:0424/144549.236883:1081641511:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000c30\n[11647:11647:0424/144549.236939:1081641555:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.236998:1081641620:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.237047:1081641674:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[11647:11647:0424/144549.237217:1081641843: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 } }\n[ OK ] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[18/28] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[11647:11647:0424/144549.239151:1081643770:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e10 with delay 0\n[11647:11647:0424/144549.239218:1081643834:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.239492:1081644115:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[11647:11647:0424/144549.239554:1081644193:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e10\n[11647:11647:0424/144549.239626:1081644241:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[11647:11647:0424/144549.239696:1081644327:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.239778:1081644395:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0\n[11647:11647:0424/144549.239824:1081644439:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0\n[11647:11647:0424/144549.239864:1081644482:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.239909:1081644538:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[11647:11647:0424/144549.239965:1081644580:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[11647:11647:0424/144549.240000:1081644622:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.240056:1081644682:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.240112:1081644733:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0\n[11647:11647:0424/144549.240158:1081644773:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0\n[11647:11647:0424/144549.240234:1081644864:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"744302890545079003\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.240300:1081644931:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.240367:1081644988:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 500\n[11647:11647:0424/144549.240419:1081645046:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.240472:1081645090:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000db0 with delay 60000\n[11647:11647:0424/144549.240527:1081645148:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[11647:11647:0424/144549.240576:1081645214:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.240657:1081645274:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.240808:1081645435: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: \"744302890545079003\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.240937:1081645568:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[11647:11647:0424/144549.241010:1081645637:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[11647:11647:0424/144549.241162:1081645784:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"744302890545079003\" 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\" } }\n[11647:11647:0424/144549.241233:1081645856:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"744302890545079003\"\n[11647:11647:0424/144549.241290:1081645907:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.241333:1081645973:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.241401:1081646024:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e00 with delay 1200000\n[11647:11647:0424/144549.241450:1081646076:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.241603:1081646227:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.241663:1081646284:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.241712:1081646333:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ad0 with delay 0\n[11647:11647:0424/144549.241788:1081646414: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\n[11647:11647:0424/144549.241851:1081646467:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ad0\n[11647:11647:0424/144549.241923:1081646539:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a30 with delay 0\n[11647:11647:0424/144549.241978:1081646601:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.242036:1081646653:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e10 with delay 10000\n[11647:11647:0424/144549.242098:1081646713:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a30\n[11647:11647:0424/144549.242138:1081646760:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.242213:1081646841:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.242279:1081646897:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a30 with delay 0\n[11647:11647:0424/144549.242324:1081646956:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a30\n[11647:11647:0424/144549.242445:1081647072: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\" } }\n[11647:11647:0424/144549.242738:1081647360:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e10\n[11647:11647:0424/144549.243775:1081648404: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\" } }\n[ OK ] InvalidationClientImplTest.NoRegistrationSummary (6 ms)\n[19/28] InvalidationClientImplTest.NoRegistrationSummary (6 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[11647:11647:0424/144549.244431:1081649049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c70 with delay 0\n[11647:11647:0424/144549.244496:1081649112:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[11647:11647:0424/144549.244753:1081649380:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[11647:11647:0424/144549.244811:1081649429:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c70\n[11647:11647:0424/144549.244851:1081649466:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[11647:11647:0424/144549.244929:1081649551:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[11647:11647:0424/144549.244999:1081649615:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0\n[11647:11647:0424/144549.245046:1081649661:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0\n[11647:11647:0424/144549.245085:1081649707:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[11647:11647:0424/144549.245133:1081649761:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[11647:11647:0424/144549.245188:1081649803:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[11647:11647:0424/144549.245227:1081649858:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[11647:11647:0424/144549.245288:1081649905:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424\n[11647:11647:0424/144549.245327:1081649968:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0\n[11647:11647:0424/144549.245391:1081650007:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0\n[11647:11647:0424/144549.245470:1081650087:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1829627994674948836\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[11647:11647:0424/144549.245522:1081650145:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[11647:11647:0424/144549.245582:1081650207:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 500\n[11647:11647:0424/144549.245648:1081650275:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424\n[11647:11647:0424/144549.245706:1081650328:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000aa0 with delay 60000\n[11647:11647:0424/144549.245766:1081650393:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[11647:11647:0424/144549.245818:1081650448:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.245885:1081650507:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[11647:11647:0424/144549.246037:1081650663: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: \"-1829627994674948836\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[11647:11647:0424/144549.246169:1081650791:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 0\n[11647:11647:0424/144549.246224:1081650841:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[11647:11647:0424/144549.246376:1081651003:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1829627994674948836\" 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\" } }\n[11647:11647:0424/144549.246465:1081651096:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1829627994674948836\"\n[11647:11647:0424/144549.246525:1081651152:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[11647:11647:0424/144549.246591:1081651225:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[11647:11647:0424/144549.246654:1081651282:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a30 with delay 1200000\n[11647:11647:0424/144549.246708:1081651330:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[11647:11647:0424/144549.246856:1081651478:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.246912:1081651534:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[11647:11647:0424/144549.246962:1081651595:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ad0 with delay 0\n[11647:11647:0424/144549.247046:1081651674: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\n[11647:11647:0424/144549.247110:1081651725:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ad0\n[11647:11647:0424/144549.247181:1081651797:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[11647:11647:0424/144549.247229:1081651860:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[11647:11647:0424/144549.247287:1081651909:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c70 with delay 10000\n[11647:11647:0424/144549.247349:1081651964:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[11647:11647:0424/144549.247389:1081652022:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[11647:11647:0424/144549.247702:1081652338:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c70\n[11647:11647:0424/144549.249527:1081654142:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000aa0\n[11647:11647:0424/144549.275385:1081680013:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000a30\n[11647:11647:0424/144549.275482:1081680100:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.275565:1081680183:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[11647:11647:0424/144549.275616:1081680234:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[11647:11647:0424/144549.275845:1081680484: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 }\n[11647:11647:0424/144549.275922:1081680545:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424\n[11647:11647:0424/144549.275993:1081680617:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000aa0 with delay 500\n[11647:11647:0424/144549.276055:1081680680:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[11647:11647:0424/144549.276109:1081680727:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000c70 with delay 1200000\n[11647:11647:0424/144549.276167:1081680783:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000aa0\n[11647:11647:0424/144549.276207:1081680833:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.276305:1081680932:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[11647:11647:0424/144549.276370:1081680998:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[11647:11647:0424/144549.276650:1081681272: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 } }\n[ OK ] InvalidationClientImplTest.Heartbeats (34 ms)\n[20/28] InvalidationClientImplTest.Heartbeats (34 ms)\n[ RUN ] ProtocolHandlerTest.TokenMissing\n[11652:11652:0424/144549.260855:1081665522:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b60 with delay 0\n[11652:11652:0424/144549.261059:1081665724:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b60\n[11652:11652:0424/144549.261631:1081666286: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 }\n[11652:11652:0424/144549.261801:1081666450:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424\n[11652:11652:0424/144549.261937:1081666586:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 500\n[11652:11652:0424/144549.262069:1081666718:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70\n[11652:11652:0424/144549.262277:1081666930:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[11652:11652:0424/144549.262396:1081667049:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (3 ms)\n[21/28] ProtocolHandlerTest.TokenMissing (3 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[11652:11652:0424/144549.263335:1081667992:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0\n[11652:11652:0424/144549.263491:1081668135:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70\n[11652:11652:0424/144549.263643:1081668290:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424\n[11652:11652:0424/144549.263770:1081668431:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b60 with delay 500\n[11652:11652:0424/144549.263912:1081668566:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b60\n[11652:11652:0424/144549.264258:1081668901:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[11652:11652:0424/144549.264458:1081669106: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 }\n[11652:11652:0424/144549.264645:1081669289: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 } }\n[11652:11652:0424/144549.264955:1081669597: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 } } }\n[11652:11652:0424/144549.265262:1081669909: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 } } }\n[ OK ] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)\n[22/28] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[11652:11652:0424/144549.266043:1081670687:INFO:protocol-handler.cc(139)] Incoming message: { }\n[11652:11652:0424/144549.266145:1081670786:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[11652:11652:0424/144549.266228:1081670877:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[23/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[11652:11652:0424/144549.266754:1081671403:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1619335848 with a delay 10000, Now = 0\n[11652:11652:0424/144549.266862:1081671500:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009d0 with delay 10\n[11652:11652:0424/144549.266982:1081671628:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009d0\n[11652:11652:0424/144549.267089:1081671742:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[11652:11652:0424/144549.267203:1081671846:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335848 with a delay 60000, Now = 10000\n[11652:11652:0424/144549.267314:1081671963:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009e0 with delay 60\n[11652:11652:0424/144549.267442:1081672058:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7010000009e0\n[11652:11652:0424/144549.267481:1081672096:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[11652:11652:0424/144549.267517:1081672132:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335848 with a delay 60000, Now = 70000\n[11652:11652:0424/144549.267552:1081672168:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000009d0 with delay 60\n[11652:11652:0424/144549.267595:1081672210:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000009d0\n[11652:11652:0424/144549.267629:1081672245:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[11652:11652:0424/144549.267664:1081672279:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335848 with a delay 60000, Now = 130000\n[11652:11652:0424/144549.267699:1081672314:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7010000009e0 with delay 60\n[11652:11652:0424/144549.267735:1081672350:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7010000009e0\n[11652:11652:0424/144549.267769:1081672384:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[11652:11652:0424/144549.267803:1081672418:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335848 with a delay 60000, Now = 190000\n[11652:11652:0424/144549.267838:1081672453:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000009d0 with delay 60\n[11652:11652:0424/144549.267874:1081672489:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000009d0\n[11652:11652:0424/144549.267907:1081672523:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[11652:11652:0424/144549.267941:1081672556:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335848 with a delay 60000, Now = 250000\n[11652:11652:0424/144549.267976:1081672591:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7010000009e0 with delay 60\n[11652:11652:0424/144549.268012:1081672627:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7010000009e0\n[11652:11652:0424/144549.268045:1081672661:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[11652:11652:0424/144549.268079:1081672698:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335848 with a delay 60000, Now = 310000\n[11652:11652:0424/144549.268118:1081672733:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000009d0 with delay 60\n[11652:11652:0424/144549.268154:1081672769:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000009d0\n[11652:11652:0424/144549.268188:1081672803:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[11652:11652:0424/144549.268227:1081672842:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335848 with a delay 60000, Now = 370000\n[11652:11652:0424/144549.268263:1081672878:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7010000009e0 with delay 60\n[11652:11652:0424/144549.268307:1081672966:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7010000009e0\n[11652:11652:0424/144549.268419:1081673056:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (3 ms)\n[24/28] RecurringTaskTest.PeriodicTask (3 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[11652:11652:0424/144549.269857:1081674509:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1619335664 with a delay 10000, Now = 0\n[11652:11652:0424/144549.269982:1081674640:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009e0 with delay 10\n[11652:11652:0424/144549.270113:1081674748:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009e0\n[11652:11652:0424/144549.270216:1081674860:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[11652:11652:0424/144549.270328:1081674970:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335664 with a delay 50000, Now = 10000\n[11652:11652:0424/144549.270437:1081675073:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009d0 with delay 50\n[11652:11652:0424/144549.270537:1081675198:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000009d0\n[11652:11652:0424/144549.270648:1081675292:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[11652:11652:0424/144549.270736:1081675390:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335664 with a delay 149000, Now = 60000\n[11652:11652:0424/144549.270853:1081675496:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7010000009e0 with delay 149\n[11652:11652:0424/144549.270960:1081675608:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7010000009e0\n[11652:11652:0424/144549.271078:1081675723:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[11652:11652:0424/144549.271196:1081675842:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335664 with a delay 248000, Now = 210000\n[11652:11652:0424/144549.271301:1081675953:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000009d0 with delay 248\n[11652:11652:0424/144549.271445:1081676089:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000009d0\n[11652:11652:0424/144549.271557:1081676210:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[11652:11652:0424/144549.271660:1081676291:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335664 with a delay 446000, Now = 460000\n[11652:11652:0424/144549.271741:1081676385:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7010000009e0 with delay 446\n[11652:11652:0424/144549.271869:1081676514:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7010000009e0\n[11652:11652:0424/144549.271957:1081676603:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[11652:11652:0424/144549.272059:1081676709:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335664 with a delay 842000, Now = 910000\n[11652:11652:0424/144549.272161:1081676789:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000009d0 with delay 842\n[11652:11652:0424/144549.272266:1081676881:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000009d0\n[11652:11652:0424/144549.272303:1081676918:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[11652:11652:0424/144549.272346:1081676962:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335664 with a delay 1040000, Now = 1760000\n[11652:11652:0424/144549.272394:1081677013:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7010000009e0 with delay 1040\n[11652:11652:0424/144549.272462:1081677077:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7010000009e0\n[11652:11652:0424/144549.272496:1081677111:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[11652:11652:0424/144549.272536:1081677151:INFO:recurring-task.cc(55)] [Retry] Scheduling 1619335664 with a delay 1040000, Now = 2800000\n[11652:11652:0424/144549.272571:1081677186:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000009d0 with delay 1040\n[11652:11652:0424/144549.272640:1081677256:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000009d0\n[11652:11652:0424/144549.272674:1081677289:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (4 ms)\n[25/28] RecurringTaskTest.ExponentialBackoffTask (4 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[11652:11652:0424/144549.273905:1081678548:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1619335704 with a delay 10000, Now = 0\n[11652:11652:0424/144549.273994:1081678639:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009d0 with delay 10\n[11652:11652:0424/144549.274094:1081678734:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009d0\n[11652:11652:0424/144549.274186:1081678820:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[11652:11652:0424/144549.274284:1081678930:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1619335704 with a delay 10000, Now = 10000\n[11652:11652:0424/144549.274394:1081679031:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009d0 with delay 10\n[11652:11652:0424/144549.274475:1081679108:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000009d0\n[11652:11652:0424/144549.274548:1081679203:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (2 ms)\n[26/28] RecurringTaskTest.OneShotTask (2 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[11652:11652:0424/144549.276067:1081680715:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000009d0 with delay 920\n[11652:11652:0424/144549.276198:1081680837:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.276633:1081681287:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000009d0 with delay 45000\n[11652:11652:0424/144549.277798:1081682433:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009d0\n[ OK ] ThrottleTest.ThrottlingScripted (2 ms)\n[27/28] ThrottleTest.ThrottlingScripted (2 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[11652:11652:0424/144549.278013:1081682647:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009d0 with delay 990\n[11652:11652:0424/144549.278138:1081682780:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.278218:1081682833:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.278282:1081682897:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.278318:1081682933:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.278391:1081683006:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.278428:1081683043:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.278491:1081683106:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.278528:1081683142:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.278596:1081683210:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.278631:1081683246:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.278694:1081683309:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.278731:1081683373:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7010000009e0 with delay 54000\n[11652:11652:0424/144549.280432:1081685048:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.280481:1081685096:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.280544:1081685159:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.280580:1081685201:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.280649:1081685263:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.280685:1081685299:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.280747:1081685361:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.280785:1081685400:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.280847:1081685462:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.280883:1081685498:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.280945:1081685560:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.280981:1081685596:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.281047:1081685662:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.281082:1081685701:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000009d0 with delay 54000\n[11652:11652:0424/144549.282720:1081687335:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.282762:1081687377:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.282827:1081687442:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.282865:1081687480:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.282928:1081687543:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.282965:1081687579:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.283028:1081687643:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.283065:1081687681:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.283134:1081687748:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.283171:1081687786:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.283234:1081687848:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.283270:1081687885:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.283333:1081687956:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.283377:1081687993:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7010000009e0 with delay 54000\n[11652:11652:0424/144549.285024:1081689640:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.285077:1081689695:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.285145:1081689760:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.285182:1081689797:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.285252:1081689866:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.285288:1081689903:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.285358:1081689973:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.285395:1081690010:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.285458:1081690072:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.285494:1081690109:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.285558:1081690172:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.285600:1081690215:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7010000009e0 with delay 1000\n[11652:11652:0424/144549.285663:1081690278:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7010000009e0\n[11652:11652:0424/144549.285699:1081690314:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000009d0 with delay 54000\n[11652:11652:0424/144549.287323:1081691946:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.287380:1081691995:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.287487:1081692102:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.287524:1081692139:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.287591:1081692206:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.287628:1081692243:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.287691:1081692305:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.287727:1081692341:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.287789:1081692403:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.287825:1081692439:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.287887:1081692502:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.287923:1081692538:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000009d0 with delay 1000\n[11652:11652:0424/144549.287985:1081692600:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000009d0\n[11652:11652:0424/144549.288020:1081692636:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7010000009e0 with delay 54000\n[11652:11652:0424/144549.289660:1081694275:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7010000009e0\n[ OK ] ThrottleTest.ThrottlingStorm (12 ms)\n[28/28] ThrottleTest.ThrottlingStorm (12 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "c67fc3538e7de53d8d8506306def2515a5e98d79", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "446a2109b8571d11", "server_versions": [ "4274-a0a5f8c" ], "started_ts": "2019-04-24T21:45:37.990664", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:linux_chromium_msan_rel_ng", "buildnumber:1438", "cpu:x86-64", "data:70ccc297f3f54234f5dcc9db1a7dca7956c77781", "gerrit:https://chromium-review.googlesource.com/c/1582233/3", "gpu:none", "master:tryserver.chromium.linux", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "patch_project:chromium/src", "pool:Chrome", "priority:30", "project:chromium", "purpose:ManualTS", "purpose:luci", "purpose:pre-commit", "service_account:none", "slavename:swarm1907-c4", "spec_name:chromium.try:linux_chromium_msan_rel_ng", "stepname:cacheinvalidation_unittests (with patch)", "swarming.pool.template:none", "swarming.pool.version:82448814faa4820fccac763aebde958e33abecf8", "user:None" ], "task_id": "446a2109b8571d10", "try_number": "1" } ] }