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-central1-c-572-z14q" ] }, { "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": [ "4267-53b17d5" ] }, { "key": "zone", "value": [ "us", "us-central", "us-central1", "us-central1-c" ] } ], "bot_id": "chrome-trusty-us-central1-c-572-z14q", "bot_version": "bd68e04e43fc4d1b7b5b65890a29c5d5bae55ab1423851733f92abd7e13dda14", "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-19T18:47:19.143317", "cost_saved_usd": 0.0009356000780461651, "created_ts": "2019-04-20T21:17:17.304859", "deduped_from": "444fbe0a70bafa11", "duration": 1.9393069744110107, "modified_ts": "2019-04-20T21:17:17.317683", "name": "cacheinvalidation_unittests/Ubuntu-14.04/1df153a0c9/Linux TSan Tests/37313", "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\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 NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\n TSAN_OPTIONS=symbolize=1 external_symbolizer_path=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer handle_abort=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioa8nUBm/output.json --no-sandbox\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.TokenMissing\n[646:646:0419/114716.775482:12425916375:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b60 with delay 0\n[646:646:0419/114716.775632:12425916522:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b60\n[646:646:0419/114716.776192:12425917085: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[646:646:0419/114716.776355:12425917246:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7112 with a delay 500000, Now = 210919424\n[646:646:0419/114716.776478:12425917366:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b70 with delay 500\n[646:646:0419/114716.776602:12425917484:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b70\n[646:646:0419/114716.776856:12425917744:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[646:646:0419/114716.776979:12425917863:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (4 ms)\n[1/28] ProtocolHandlerTest.TokenMissing (4 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[646:646:0419/114716.778199:12425919090:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b70 with delay 0\n[646:646:0419/114716.778320:12425919211:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b70\n[646:646:0419/114716.778465:12425919355:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7400 with a delay 500000, Now = 210919424\n[646:646:0419/114716.778581:12425919471:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b60 with delay 500\n[646:646:0419/114716.778690:12425919575:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b60\n[646:646:0419/114716.779019:12425919903:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[646:646:0419/114716.779234:12425920119: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[646:646:0419/114716.779442:12425920325: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[646:646:0419/114716.779892:12425920775: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[646:646:0419/114716.780318:12425921209: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 (3 ms)\n[2/28] ProtocolHandlerTest.InvalidOutboundMessage (3 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[646:646:0419/114716.781546:12425922437:INFO:protocol-handler.cc(139)] Incoming message: { }\n[646:646:0419/114716.781654:12425922542:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[646:646:0419/114716.781758:12425922646:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (2 ms)\n[3/28] ProtocolHandlerTest.UnparseableInboundMessage (2 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[646:646:0419/114716.782542:12425923430:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -1178075736 with a delay 10000, Now = 0\n[646:646:0419/114716.782652:12425923539:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009d0 with delay 10\n[646:646:0419/114716.782762:12425923644:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009d0\n[646:646:0419/114716.782890:12425923776:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[646:646:0419/114716.782994:12425923878:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 60000, Now = 10000\n[646:646:0419/114716.783118:12425924027:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009e0 with delay 60\n[646:646:0419/114716.783271:12425924156:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7b04000009e0\n[646:646:0419/114716.783360:12425924256:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[646:646:0419/114716.783455:12425924340:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 60000, Now = 70000\n[646:646:0419/114716.783536:12425924419:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7b04000009d0 with delay 60\n[646:646:0419/114716.783614:12425924496:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7b04000009d0\n[646:646:0419/114716.783691:12425924575:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[646:646:0419/114716.783769:12425924650:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 60000, Now = 130000\n[646:646:0419/114716.783848:12425924729:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7b04000009e0 with delay 60\n[646:646:0419/114716.783926:12425924806:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7b04000009e0\n[646:646:0419/114716.784001:12425924881:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[646:646:0419/114716.784076:12425924959:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 60000, Now = 190000\n[646:646:0419/114716.784152:12425925035:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7b04000009d0 with delay 60\n[646:646:0419/114716.784228:12425925111:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7b04000009d0\n[646:646:0419/114716.784303:12425925186:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[646:646:0419/114716.784391:12425925274:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 60000, Now = 250000\n[646:646:0419/114716.784468:12425925351:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7b04000009e0 with delay 60\n[646:646:0419/114716.784545:12425925429:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7b04000009e0\n[646:646:0419/114716.784620:12425925503:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[646:646:0419/114716.784697:12425925581:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 60000, Now = 310000\n[646:646:0419/114716.784776:12425925658:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7b04000009d0 with delay 60\n[646:646:0419/114716.784855:12425925735:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7b04000009d0\n[646:646:0419/114716.784929:12425925809:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[646:646:0419/114716.785002:12425925883:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 60000, Now = 370000\n[646:646:0419/114716.785083:12425925965:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7b04000009e0 with delay 60\n[646:646:0419/114716.785159:12425926043:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7b04000009e0\n[646:646:0419/114716.785243:12425926130:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (3 ms)\n[4/28] RecurringTaskTest.PeriodicTask (3 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[646:646:0419/114716.786178:12425927067:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -1178075736 with a delay 10000, Now = 0\n[646:646:0419/114716.786314:12425927209:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009e0 with delay 10\n[646:646:0419/114716.786426:12425927315:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009e0\n[646:646:0419/114716.786523:12425927410:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[646:646:0419/114716.786608:12425927492:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 50000, Now = 10000\n[646:646:0419/114716.786717:12425927598:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009d0 with delay 50\n[646:646:0419/114716.786822:12425927711:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7b04000009d0\n[646:646:0419/114716.786920:12425927806:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[646:646:0419/114716.787020:12425927913:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 149000, Now = 60000\n[646:646:0419/114716.787129:12425928041:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7b04000009e0 with delay 149\n[646:646:0419/114716.787268:12425928149:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7b04000009e0\n[646:646:0419/114716.787363:12425928260:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[646:646:0419/114716.787472:12425928359:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 248000, Now = 210000\n[646:646:0419/114716.787570:12425928459:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7b04000009d0 with delay 248\n[646:646:0419/114716.787679:12425928566:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7b04000009d0\n[646:646:0419/114716.787787:12425928674:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[646:646:0419/114716.787883:12425928770:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 446000, Now = 460000\n[646:646:0419/114716.788002:12425928886:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7b04000009e0 with delay 446\n[646:646:0419/114716.788107:12425928993:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7b04000009e0\n[646:646:0419/114716.788201:12425929084:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[646:646:0419/114716.788302:12425929186:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 842000, Now = 910000\n[646:646:0419/114716.788425:12425929309:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7b04000009d0 with delay 842\n[646:646:0419/114716.788521:12425929406:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7b04000009d0\n[646:646:0419/114716.788600:12425929483:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[646:646:0419/114716.788676:12425929559:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 1040000, Now = 1760000\n[646:646:0419/114716.788753:12425929635:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7b04000009e0 with delay 1040\n[646:646:0419/114716.788846:12425929728:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7b04000009e0\n[646:646:0419/114716.788926:12425929806:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[646:646:0419/114716.789002:12425929883:INFO:recurring-task.cc(55)] [Retry] Scheduling -1178075736 with a delay 1040000, Now = 2800000\n[646:646:0419/114716.789081:12425929963:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7b04000009d0 with delay 1040\n[646:646:0419/114716.789183:12425930063:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7b04000009d0\n[646:646:0419/114716.789255:12425930137:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[5/28] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[646:646:0419/114716.790147:12425931032:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -1178075808 with a delay 10000, Now = 0\n[646:646:0419/114716.790274:12425931161:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009d0 with delay 10\n[646:646:0419/114716.790402:12425931287:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009d0\n[646:646:0419/114716.790494:12425931382:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[646:646:0419/114716.790597:12425931482:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -1178075808 with a delay 10000, Now = 10000\n[646:646:0419/114716.790707:12425931591:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009d0 with delay 10\n[646:646:0419/114716.790803:12425931687:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7b04000009d0\n[646:646:0419/114716.790913:12425931798:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (1 ms)\n[6/28] RecurringTaskTest.OneShotTask (1 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[646:646:0419/114716.792012:12425932900:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7b04000009d0 with delay 920\n[646:646:0419/114716.792143:12425933031:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000009d0\n[646:646:0419/114716.792424:12425933310:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7b04000009d0 with delay 45000\n[646:646:0419/114716.793173:12425934061:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b04000009d0\n[ OK ] ThrottleTest.ThrottlingScripted (2 ms)\n[7/28] ThrottleTest.ThrottlingScripted (2 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[646:646:0419/114716.793594:12425934486:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009d0 with delay 990\n[646:646:0419/114716.793727:12425934615:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000009d0\n[646:646:0419/114716.793870:12425934752:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.793977:12425934860:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7b04000009d0\n[646:646:0419/114716.794059:12425934943:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.794166:12425935047:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7b04000009d0\n[646:646:0419/114716.794249:12425935133:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.794359:12425935250:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7b04000009d0\n[646:646:0419/114716.794453:12425935335:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.794554:12425935437:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7b04000009d0\n[646:646:0419/114716.794639:12425935522:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.794742:12425935623:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7b04000009d0\n[646:646:0419/114716.794836:12425935723:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7b04000009e0 with delay 54000\n[646:646:0419/114716.796361:12425937256:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b04000009e0\n[646:646:0419/114716.796473:12425937354:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.796576:12425937460:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7b04000009e0\n[646:646:0419/114716.796664:12425937549:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.796772:12425937652:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7b04000009e0\n[646:646:0419/114716.796852:12425937735:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.796951:12425937833:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7b04000009e0\n[646:646:0419/114716.797028:12425937909:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.797126:12425938007:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7b04000009e0\n[646:646:0419/114716.797205:12425938086:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.797302:12425938182:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7b04000009e0\n[646:646:0419/114716.797391:12425938271:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.797491:12425938372:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7b04000009e0\n[646:646:0419/114716.797567:12425938450:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7b04000009d0 with delay 54000\n[646:646:0419/114716.799055:12425939940:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7b04000009d0\n[646:646:0419/114716.799169:12425940059:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.799284:12425940165:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7b04000009d0\n[646:646:0419/114716.799379:12425940261:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.799484:12425940366:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7b04000009d0\n[646:646:0419/114716.799562:12425940447:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.799677:12425940556:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7b04000009d0\n[646:646:0419/114716.799754:12425940636:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.799858:12425940740:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7b04000009d0\n[646:646:0419/114716.799938:12425940818:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.800035:12425940916:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7b04000009d0\n[646:646:0419/114716.800114:12425940995:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.800212:12425941092:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7b04000009d0\n[646:646:0419/114716.800291:12425941173:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7b04000009e0 with delay 54000\n[646:646:0419/114716.801773:12425942655:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7b04000009e0\n[646:646:0419/114716.801865:12425942746:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.801970:12425942855:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7b04000009e0\n[646:646:0419/114716.802054:12425942936:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.802167:12425943047:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7b04000009e0\n[646:646:0419/114716.802249:12425943131:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.802353:12425943247:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7b04000009e0\n[646:646:0419/114716.802453:12425943337:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.802555:12425943437:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7b04000009e0\n[646:646:0419/114716.802631:12425943513:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.802729:12425943608:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7b04000009e0\n[646:646:0419/114716.802805:12425943684:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7b04000009e0 with delay 1000\n[646:646:0419/114716.802903:12425943786:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7b04000009e0\n[646:646:0419/114716.802983:12425943867:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7b04000009d0 with delay 54000\n[646:646:0419/114716.804495:12425945380:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7b04000009d0\n[646:646:0419/114716.804596:12425945480:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.804703:12425945585:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7b04000009d0\n[646:646:0419/114716.804788:12425945670:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.804899:12425945781:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7b04000009d0\n[646:646:0419/114716.804980:12425945859:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.805076:12425945958:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7b04000009d0\n[646:646:0419/114716.805152:12425946033:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.805254:12425946135:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7b04000009d0\n[646:646:0419/114716.805331:12425946215:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.805438:12425946318:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7b04000009d0\n[646:646:0419/114716.805512:12425946395:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7b04000009d0 with delay 1000\n[646:646:0419/114716.805613:12425946492:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7b04000009d0\n[646:646:0419/114716.805688:12425946569:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7b04000009e0 with delay 54000\n[646:646:0419/114716.807228:12425948110:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7b04000009e0\n[ OK ] ThrottleTest.ThrottlingStorm (14 ms)\n[8/28] ThrottleTest.ThrottlingStorm (14 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[645:645:0419/114716.766228:12425907118:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b60 with delay 0\n[645:645:0419/114716.767076:12425907960:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b60\n[645:645:0419/114716.767563:12425908451: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[645:645:0419/114716.767703:12425908586:INFO:recurring-task.cc(55)] [Startup] Scheduling 7112 with a delay 500000, Now = 210919424\n[645:645:0419/114716.767810:12425908691:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000bf0 with delay 500\n[645:645:0419/114716.767921:12425908806:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000bf0\n[645:645:0419/114716.768594:12425909480: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[9/28] ProtocolHandlerTest.SendInitializeOnly (5 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[645:645:0419/114716.771099:12425911984: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[10/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[645:645:0419/114716.772255:12425913145:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0\n[645:645:0419/114716.772429:12425913321:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b20 with delay 0\n[645:645:0419/114716.772542:12425913428:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000aa0 with delay 0\n[645:645:0419/114716.772687:12425913566:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ae0 with delay 0\n[645:645:0419/114716.772767:12425913647:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a90 with delay 0\n[645:645:0419/114716.772866:12425913747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[645:645:0419/114716.773798:12425914682:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0\n[645:645:0419/114716.774124:12425915013: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[645:645:0419/114716.774272:12425915160:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7400 with a delay 500000, Now = 210919424\n[645:645:0419/114716.774398:12425915282:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c40 with delay 500\n[645:645:0419/114716.774498:12425915382:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b20\n[645:645:0419/114716.774599:12425915480:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000aa0\n[645:645:0419/114716.774686:12425915569:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ae0\n[645:645:0419/114716.774772:12425915653:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000a90\n[645:645:0419/114716.774858:12425915737:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[645:645:0419/114716.774994:12425915880:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[645:645:0419/114716.775120:12425916033:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c40\n[645:645:0419/114716.775512:12425916394:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[645:645:0419/114716.776525:12425917412: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 (7 ms)\n[11/28] ProtocolHandlerTest.SendMultipleMessageTypes (7 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[645:645:0419/114716.780189:12425921075: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 (2 ms)\n[12/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[645:645:0419/114716.781623:12425922517: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[645:645:0419/114716.781845:12425922731: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[645:645:0419/114716.782104:12425922986: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[645:645:0419/114716.782381:12425923264: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 (2 ms)\n[13/28] ProtocolHandlerTest.InvalidInboundMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[645:645:0419/114716.783691:12425924576: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[645:645:0419/114716.784023:12425924906: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 (2 ms)\n[14/28] ProtocolHandlerTest.MajorVersionMismatch (2 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[645:645:0419/114716.785282:12425926169: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[15/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[645:645:0419/114716.786575:12425927462: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[645:645:0419/114716.786702:12425927591:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a20 with delay 0\n[645:645:0419/114716.786819:12425927702:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000a20\n[645:645:0419/114716.787047:12425927936: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[645:645:0419/114716.787185:12425928069:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7784 with a delay 500000, Now = 210919424\n[645:645:0419/114716.787274:12425928158:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a30 with delay 500\n[645:645:0419/114716.787368:12425928264:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a30\n[645:645:0419/114716.787476:12425928359:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (24 ms)\n[16/28] ProtocolHandlerTest.ConfigMessage (24 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[645:645:0419/114716.810644:12425951527: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 (2 ms)\n[17/28] ProtocolHandlerTest.ErrorMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[645:645:0419/114716.811880:12425952764: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[18/28] ProtocolHandlerTest.TokenMismatch (1 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[643:643:0419/114716.769329:12425910218:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c60 with delay 0\n[643:643:0419/114716.769781:12425910664:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.770736:12425911627:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e30 with delay 0\n[643:643:0419/114716.770860:12425911747:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c60\n[643:643:0419/114716.770983:12425911869:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e30\n[643:643:0419/114716.771206:12425912098:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.771469:12425912355:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e80 with delay 0\n[643:643:0419/114716.771587:12425912468:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e80\n[643:643:0419/114716.771670:12425912557:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.771771:12425912653:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e30 with delay 0\n[643:643:0419/114716.771870:12425912751:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e30\n[643:643:0419/114716.771970:12425912852:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.772097:12425912988:INFO:recurring-task.cc(55)] [Startup] Scheduling 7112 with a delay 0, Now = 210919424\n[643:643:0419/114716.772210:12425913093:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e80 with delay 0\n[643:643:0419/114716.772311:12425913197:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e80\n[643:643:0419/114716.772551:12425913438:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-514102153538038425\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.772660:12425913545:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7496 with a delay 500000, Now = 210919424\n[643:643:0419/114716.772766:12425913653:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e30 with delay 500\n[643:643:0419/114716.772879:12425913765:INFO:recurring-task.cc(55)] [Retry] Scheduling 7112 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.772988:12425913890:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000df0 with delay 60000\n[643:643:0419/114716.773115:12425914001:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e30\n[643:643:0419/114716.773215:12425914103:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.773445:12425914329:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.773873:12425914761: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: \"-514102153538038425\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.774290:12425915180:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e30 with delay 0\n[643:643:0419/114716.774432:12425915319:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e30\n[643:643:0419/114716.774815:12425915707:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-514102153538038425\" 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[643:643:0419/114716.775004:12425915892:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-514102153538038425\"\n[643:643:0419/114716.775108:12425915993:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.775254:12425916141:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.775387:12425916272:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e70 with delay 1200000\n[643:643:0419/114716.775522:12425916405:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.775918:12425916810:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.776034:12425916922:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[643:643:0419/114716.776136:12425917022:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e80 with delay 0\n[643:643:0419/114716.776306:12425917199: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[643:643:0419/114716.776430:12425917313:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e80\n[643:643:0419/114716.776663:12425917544:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ea0 with delay 0\n[643:643:0419/114716.776766:12425917653:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.776867:12425917752:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c60 with delay 10000\n[643:643:0419/114716.776974:12425917855:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ea0\n[643:643:0419/114716.777054:12425917939:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[ OK ] InvalidationClientImplTest.Start (10 ms)\n[19/28] InvalidationClientImplTest.Start (10 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[643:643:0419/114716.778570:12425919455:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0\n[643:643:0419/114716.778709:12425919596:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (2 ms)\n[20/28] InvalidationClientImplTest.GenerateNonce (2 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[643:643:0419/114716.779973:12425920856:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e60 with delay 0\n[643:643:0419/114716.780107:12425920991:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.780934:12425921820:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ec0 with delay 0\n[643:643:0419/114716.781041:12425921922:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e60\n[643:643:0419/114716.781134:12425922013:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ec0\n[643:643:0419/114716.781322:12425922205:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.781500:12425922383:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[643:643:0419/114716.781614:12425922496:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[643:643:0419/114716.781695:12425922577:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.781795:12425922684:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ec0 with delay 0\n[643:643:0419/114716.781894:12425922776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ec0\n[643:643:0419/114716.781977:12425922861:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.782075:12425922961:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[643:643:0419/114716.782185:12425923067:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[643:643:0419/114716.782275:12425923157:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[643:643:0419/114716.782477:12425923361:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6103821107886754838\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.782590:12425923476:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7112 with a delay 500000, Now = 210919424\n[643:643:0419/114716.782694:12425923577:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ec0 with delay 500\n[643:643:0419/114716.782784:12425923668:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.782901:12425923785:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ee0 with delay 60000\n[643:643:0419/114716.783001:12425923889:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ec0\n[643:643:0419/114716.783092:12425923980:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.783241:12425924127:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.783644:12425924526: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: \"6103821107886754838\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.783933:12425924816:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ec0 with delay 0\n[643:643:0419/114716.784036:12425924923:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ec0\n[643:643:0419/114716.784396:12425925283:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6103821107886754838\" 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[643:643:0419/114716.784548:12425925432:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6103821107886754838\"\n[643:643:0419/114716.784646:12425925529:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.784768:12425925652:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.784872:12425925761:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ef0 with delay 1200000\n[643:643:0419/114716.784982:12425925870:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.785312:12425926201:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.785425:12425926313:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[643:643:0419/114716.785528:12425926409:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f00 with delay 0\n[643:643:0419/114716.785684:12425926565: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[643:643:0419/114716.785796:12425926681:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f00\n[643:643:0419/114716.785984:12425926872:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 0\n[643:643:0419/114716.786093:12425926976:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.786176:12425927067:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e60 with delay 10000\n[643:643:0419/114716.786274:12425927160:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f20\n[643:643:0419/114716.786365:12425927262:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.786516:12425927397:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f20 with delay 0\n[643:643:0419/114716.786612:12425927495:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f20\n[643:643:0419/114716.786743:12425927628:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[643:643:0419/114716.786863:12425927744:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[643:643:0419/114716.786969:12425927852:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[643:643:0419/114716.787182:12425928071:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7112 with a delay 500000, Now = 211469424\n[643:643:0419/114716.787296:12425928185:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f00 with delay 500\n[643:643:0419/114716.787407:12425928291:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7784 with a delay 60000000, Now = 211469424\n[643:643:0419/114716.787498:12425928381:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f10 with delay 60000\n[643:643:0419/114716.787599:12425928489:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f00\n[643:643:0419/114716.787708:12425928592:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.787835:12425928720:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.787934:12425928823:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[643:643:0419/114716.788456:12425929343: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[643:643:0419/114716.788676:12425929564:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.788875:12425929757:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400000f00 with delay 0\n[643:643:0419/114716.788981:12425929865:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f00\n[643:643:0419/114716.789624:12425930511: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[643:643:0419/114716.789865:12425930750: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[643:643:0419/114716.790104:12425930993:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[643:643:0419/114716.790396:12425931281:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[643:643:0419/114716.790627:12425931512:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[643:643:0419/114716.790929:12425931812:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e60\n[ OK ] InvalidationClientImplTest.Register (13 ms)\n[21/28] InvalidationClientImplTest.Register (13 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[643:643:0419/114716.793169:12425934057:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000da0 with delay 0\n[643:643:0419/114716.793314:12425934206:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.794170:12425935057:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 0\n[643:643:0419/114716.794264:12425935147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000da0\n[643:643:0419/114716.794369:12425935260:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c10\n[643:643:0419/114716.794562:12425935448:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.794733:12425935620:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0\n[643:643:0419/114716.794839:12425935722:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20\n[643:643:0419/114716.794930:12425935813:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.795018:12425935903:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 0\n[643:643:0419/114716.795116:12425936019:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c10\n[643:643:0419/114716.795227:12425936113:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.795338:12425936220:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[643:643:0419/114716.795450:12425936334:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0\n[643:643:0419/114716.795543:12425936428:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20\n[643:643:0419/114716.795720:12425936615:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4972089790840031581\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.795829:12425936715:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[643:643:0419/114716.795923:12425936807:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 500\n[643:643:0419/114716.796017:12425936898:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.796116:12425936998:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b80 with delay 60000\n[643:643:0419/114716.796215:12425937096:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c10\n[643:643:0419/114716.796306:12425937192:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.796439:12425937323:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.796811:12425937697: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: \"-4972089790840031581\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.797109:12425938005:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c10 with delay 0\n[643:643:0419/114716.797227:12425938112:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c10\n[643:643:0419/114716.797580:12425938463:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4972089790840031581\" 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[643:643:0419/114716.797725:12425938608:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4972089790840031581\"\n[643:643:0419/114716.797826:12425938708:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.797938:12425938820:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.798037:12425938919:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ec0 with delay 1200000\n[643:643:0419/114716.798136:12425939019:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.798475:12425939365:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.798585:12425939469:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[643:643:0419/114716.798675:12425939564:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 0\n[643:643:0419/114716.798824:12425939715: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[643:643:0419/114716.798946:12425939827:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f20\n[643:643:0419/114716.799127:12425940025:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f50 with delay 0\n[643:643:0419/114716.799247:12425940131:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.799347:12425940239:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000da0 with delay 10000\n[643:643:0419/114716.799450:12425940334:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f50\n[643:643:0419/114716.799538:12425940430:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.799667:12425940547:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.799825:12425940709:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f50 with delay 0\n[643:643:0419/114716.799927:12425940812:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f50\n[643:643:0419/114716.800527:12425941417: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[643:643:0419/114716.800761:12425941645: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[643:643:0419/114716.800984:12425941867: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[643:643:0419/114716.801259:12425942143: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[643:643:0419/114716.801514:12425942395: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[643:643:0419/114716.801700:12425942585:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f50 with delay 0\n[643:643:0419/114716.801803:12425942692:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f20 with delay 0\n[643:643:0419/114716.801903:12425942785:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f30 with delay 0\n[643:643:0419/114716.801987:12425942875:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f50\n[643:643:0419/114716.802113:12425942996:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7976 with a delay 500000, Now = 211519424\n[643:643:0419/114716.802201:12425943086:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000c10 with delay 500\n[643:643:0419/114716.802293:12425943181:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f20\n[643:643:0419/114716.802404:12425943285:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f30\n[643:643:0419/114716.802503:12425943388:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7b0400000c10\n[643:643:0419/114716.802588:12425943475:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.802714:12425943598:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.802810:12425943697:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[643:643:0419/114716.803353:12425944247: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 (12 ms)\n[22/28] InvalidationClientImplTest.Invalidations (12 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[643:643:0419/114716.804963:12425945850:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e90 with delay 0\n[643:643:0419/114716.805105:12425945988:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.805701:12425946584:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[643:643:0419/114716.805801:12425946685:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e90\n[643:643:0419/114716.805895:12425946775:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[643:643:0419/114716.806064:12425946948:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.806207:12425947089:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[643:643:0419/114716.806302:12425947188:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[643:643:0419/114716.806399:12425947281:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.806495:12425947377:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[643:643:0419/114716.806590:12425947473:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[643:643:0419/114716.806676:12425947559:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.806771:12425947653:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[643:643:0419/114716.806873:12425947756:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[643:643:0419/114716.806965:12425947847:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[643:643:0419/114716.807181:12425948066:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-5884893776594025243\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.807287:12425948181:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[643:643:0419/114716.807400:12425948284:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 500\n[643:643:0419/114716.807487:12425948370:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.807586:12425948470:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d20 with delay 60000\n[643:643:0419/114716.807688:12425948570:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[643:643:0419/114716.807776:12425948660:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.807882:12425948765:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.808258:12425949141: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: \"-5884893776594025243\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.808557:12425949441:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000cf0 with delay 0\n[643:643:0419/114716.808649:12425949533:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[643:643:0419/114716.808980:12425949865:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-5884893776594025243\" 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[643:643:0419/114716.809118:12425950001:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-5884893776594025243\"\n[643:643:0419/114716.809222:12425950110:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.809323:12425950210:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.809433:12425950317:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000be0 with delay 1200000\n[643:643:0419/114716.809528:12425950416:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.809844:12425950727:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.809946:12425950828:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[643:643:0419/114716.810037:12425950918:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f00 with delay 0\n[643:643:0419/114716.810176:12425951057: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[643:643:0419/114716.810281:12425951163:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f00\n[643:643:0419/114716.810453:12425951336:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c00 with delay 0\n[643:643:0419/114716.810552:12425951436:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.810636:12425951521:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e90 with delay 10000\n[643:643:0419/114716.810720:12425951603:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c00\n[643:643:0419/114716.810804:12425951691:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.810909:12425951793:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.811036:12425951917:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000c00 with delay 0\n[643:643:0419/114716.811123:12425952020:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000c00\n[643:643:0419/114716.811478:12425952362: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[643:643:0419/114716.811661:12425952545: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[643:643:0419/114716.811759:12425952645:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[643:643:0419/114716.811869:12425952753:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 8456 with a delay 500000, Now = 211469424\n[643:643:0419/114716.811956:12425952841:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f00 with delay 500\n[643:643:0419/114716.812043:12425952929:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[643:643:0419/114716.812641:12425953524: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[643:643:0419/114716.812775:12425953659:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f00\n[643:643:0419/114716.812868:12425953754:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.813023:12425953904:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.813118:12425954000:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[643:643:0419/114716.813918:12425954804: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[643:643:0419/114716.814286:12425955169:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e90\n[ OK ] InvalidationClientImplTest.ServerRequests (11 ms)\n[23/28] InvalidationClientImplTest.ServerRequests (11 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[643:643:0419/114716.816263:12425957148:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 0\n[643:643:0419/114716.816430:12425957312:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.817058:12425957947:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[643:643:0419/114716.817157:12425958040:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b30\n[643:643:0419/114716.817237:12425958120:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[643:643:0419/114716.817422:12425958311:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.817594:12425958479:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ac0 with delay 0\n[643:643:0419/114716.817687:12425958571:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ac0\n[643:643:0419/114716.817769:12425958655:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.817865:12425958749:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[643:643:0419/114716.817948:12425958832:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[643:643:0419/114716.818029:12425958916:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.818124:12425959010:INFO:recurring-task.cc(55)] [Startup] Scheduling 7976 with a delay 0, Now = 210919424\n[643:643:0419/114716.818210:12425959094:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ac0 with delay 0\n[643:643:0419/114716.818295:12425959182:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ac0\n[643:643:0419/114716.818480:12425959363:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3011176452331698130\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.818575:12425959458:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7592 with a delay 500000, Now = 210919424\n[643:643:0419/114716.818659:12425959548:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 500\n[643:643:0419/114716.818751:12425959632:INFO:recurring-task.cc(55)] [Retry] Scheduling 7976 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.818841:12425959723:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ab0 with delay 60000\n[643:643:0419/114716.818933:12425959814:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[643:643:0419/114716.819022:12425959903:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.819121:12425960021:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.819501:12425960388: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: \"-3011176452331698130\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.819738:12425960624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000cf0 with delay 0\n[643:643:0419/114716.819830:12425960717:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[643:643:0419/114716.820145:12425961028:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3011176452331698130\" 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[643:643:0419/114716.820279:12425961161:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3011176452331698130\"\n[643:643:0419/114716.820385:12425961267:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.820479:12425961362:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.820564:12425961445:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b10 with delay 1200000\n[643:643:0419/114716.820654:12425961537:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.820931:12425961817:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.821031:12425961916:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[643:643:0419/114716.821120:12425962007:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ac0 with delay 0\n[643:643:0419/114716.821253:12425962137: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[643:643:0419/114716.821362:12425962254:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ac0\n[643:643:0419/114716.821526:12425962409:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000009c0 with delay 0\n[643:643:0419/114716.821620:12425962506:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.821714:12425962599:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b30 with delay 10000\n[643:643:0419/114716.821798:12425962682:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000009c0\n[643:643:0419/114716.821879:12425962762:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.821977:12425962858:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.822095:12425962979:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b04000009c0 with delay 0\n[643:643:0419/114716.822191:12425963074:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b04000009c0\n[643:643:0419/114716.822491:12425963374: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[643:643:0419/114716.822660:12425963545: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[643:643:0419/114716.822755:12425963646:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[643:643:0419/114716.823078:12425963963:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000b30\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (9 ms)\n[24/28] InvalidationClientImplTest.IncomingErrorMessage (9 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[643:643:0419/114716.825050:12425965935:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d70 with delay 0\n[643:643:0419/114716.825191:12425966076:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.825839:12425966723:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0\n[643:643:0419/114716.825930:12425966811:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000d70\n[643:643:0419/114716.826012:12425966892:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e50\n[643:643:0419/114716.826176:12425967061:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.826328:12425967212:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f30 with delay 0\n[643:643:0419/114716.826449:12425967332:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f30\n[643:643:0419/114716.826531:12425967415:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.826618:12425967509:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0\n[643:643:0419/114716.826716:12425967598:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e50\n[643:643:0419/114716.826798:12425967685:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.826909:12425967794:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[643:643:0419/114716.826999:12425967882:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f30 with delay 0\n[643:643:0419/114716.827085:12425967965:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f30\n[643:643:0419/114716.827270:12425968154:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8591037194607075298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.827382:12425968265:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[643:643:0419/114716.827464:12425968349:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 500\n[643:643:0419/114716.827552:12425968436:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.827634:12425968517:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 60000\n[643:643:0419/114716.827726:12425968613:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e50\n[643:643:0419/114716.827813:12425968703:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.827920:12425968802:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.828273:12425969155: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: \"8591037194607075298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.828524:12425969412:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e50 with delay 0\n[643:643:0419/114716.828616:12425969499:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e50\n[643:643:0419/114716.828933:12425969818:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8591037194607075298\" 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[643:643:0419/114716.829066:12425969957:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8591037194607075298\"\n[643:643:0419/114716.829163:12425970047:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.829257:12425970141:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.829348:12425970243:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 1200000\n[643:643:0419/114716.829458:12425970343:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.829744:12425970628:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.829849:12425970735:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[643:643:0419/114716.829940:12425970824:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f30 with delay 0\n[643:643:0419/114716.830074:12425970957: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[643:643:0419/114716.830185:12425971068:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f30\n[643:643:0419/114716.830355:12425971246:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f40 with delay 0\n[643:643:0419/114716.830464:12425971345:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.830544:12425971427:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000d70 with delay 10000\n[643:643:0419/114716.830631:12425971514:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f40\n[643:643:0419/114716.830710:12425971596:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.830813:12425971699:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f40 with delay 0\n[643:643:0419/114716.830910:12425971792:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f40\n[643:643:0419/114716.831038:12425971922:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[643:643:0419/114716.831210:12425972093:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7976 with a delay 500000, Now = 211469424\n[643:643:0419/114716.831300:12425972187:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f30 with delay 500\n[643:643:0419/114716.831413:12425972296:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7112 with a delay 60000000, Now = 211469424\n[643:643:0419/114716.831501:12425972382:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f50 with delay 60000\n[643:643:0419/114716.831597:12425972480:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f30\n[643:643:0419/114716.831684:12425972565:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.831796:12425972681:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.831888:12425972773:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[643:643:0419/114716.832240:12425973122: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[643:643:0419/114716.832442:12425973327:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.832556:12425973441:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400000f30 with delay 0\n[643:643:0419/114716.832644:12425973529:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f30\n[643:643:0419/114716.832923:12425973809: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[643:643:0419/114716.833091:12425973976: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[643:643:0419/114716.833184:12425974068:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[643:643:0419/114716.833413:12425974305:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[643:643:0419/114716.833954:12425974850:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000d70\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (11 ms)\n[25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (11 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[643:643:0419/114716.836164:12425977051:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c00 with delay 0\n[643:643:0419/114716.836311:12425977201:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.836809:12425977697:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 0\n[643:643:0419/114716.836912:12425977796:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c00\n[643:643:0419/114716.836996:12425977879:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b30\n[643:643:0419/114716.837160:12425978048:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.837306:12425978199:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e00 with delay 0\n[643:643:0419/114716.837418:12425978301:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e00\n[643:643:0419/114716.837500:12425978386:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.837585:12425978470:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 0\n[643:643:0419/114716.837679:12425978566:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b30\n[643:643:0419/114716.837764:12425978648:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.837859:12425978743:INFO:recurring-task.cc(55)] [Startup] Scheduling 7880 with a delay 0, Now = 210919424\n[643:643:0419/114716.837953:12425978836:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e00 with delay 0\n[643:643:0419/114716.838035:12425978918:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e00\n[643:643:0419/114716.838211:12425979095:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4091855847013291176\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.838307:12425979198:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7688 with a delay 500000, Now = 210919424\n[643:643:0419/114716.838409:12425979291:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 500\n[643:643:0419/114716.838498:12425979380:INFO:recurring-task.cc(55)] [Retry] Scheduling 7880 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.838590:12425979474:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c30 with delay 60000\n[643:643:0419/114716.838682:12425979564:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b30\n[643:643:0419/114716.838765:12425979647:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.838874:12425979759:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.839260:12425980143: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: \"4091855847013291176\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.839518:12425980404:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b30 with delay 0\n[643:643:0419/114716.839609:12425980498:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b30\n[643:643:0419/114716.839928:12425980810:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4091855847013291176\" 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[643:643:0419/114716.840051:12425980936:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4091855847013291176\"\n[643:643:0419/114716.840148:12425981030:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.840243:12425981126:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.840339:12425981221:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ec0 with delay 1200000\n[643:643:0419/114716.840439:12425981321:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.840727:12425981612:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.840836:12425981720:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[643:643:0419/114716.840922:12425981807:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e00 with delay 0\n[643:643:0419/114716.841061:12425981943: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[643:643:0419/114716.841157:12425982047:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e00\n[643:643:0419/114716.841332:12425982214:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a30 with delay 0\n[643:643:0419/114716.841440:12425982322:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.841526:12425982408:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c00 with delay 10000\n[643:643:0419/114716.841610:12425982493:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a30\n[643:643:0419/114716.841692:12425982573:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.841798:12425982684:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000a30 with delay 0\n[643:643:0419/114716.841890:12425982773:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000a30\n[643:643:0419/114716.842005:12425982890:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[643:643:0419/114716.842136:12425983023:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7688 with a delay 500000, Now = 211469424\n[643:643:0419/114716.842224:12425983109:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000e00 with delay 500\n[643:643:0419/114716.842312:12425983202:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7496 with a delay 60000000, Now = 211469424\n[643:643:0419/114716.842418:12425983301:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000ad0 with delay 60000\n[643:643:0419/114716.842513:12425983396:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000e00\n[643:643:0419/114716.842601:12425983484:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.842714:12425983595:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.842799:12425983683:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[643:643:0419/114716.843184:12425984070: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[643:643:0419/114716.843533:12425984420:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000c00\n[643:643:0419/114716.844348:12425985239:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400000c30\n[643:643:0419/114716.844451:12425985333:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7b0400000ad0\n[643:643:0419/114716.844590:12425985474: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[643:643:0419/114716.844678:12425985564:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[643:643:0419/114716.844884:12425985769: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[643:643:0419/114716.844982:12425985865:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7688 with a delay 500000, Now = 271469424\n[643:643:0419/114716.845065:12425985950:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400000c30 with delay 500\n[643:643:0419/114716.845155:12425986039:INFO:recurring-task.cc(55)] [Retry] Scheduling 7496 with a delay 60000000, Now = 271469424\n[643:643:0419/114716.845240:12425986125:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400000c00 with delay 60000\n[643:643:0419/114716.845342:12425986227:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7b0400000c30\n[643:643:0419/114716.845436:12425986320:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.845551:12425986434:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.845636:12425986520:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[643:643:0419/114716.846011:12425986896: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 (12 ms)\n[26/28] InvalidationClientImplTest.NetworkTimeouts (12 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[643:643:0419/114716.848288:12425989173:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e10 with delay 0\n[643:643:0419/114716.848444:12425989332:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.848892:12425989776:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0\n[643:643:0419/114716.848988:12425989872:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e10\n[643:643:0419/114716.849068:12425989955:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0\n[643:643:0419/114716.849234:12425990115:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.849383:12425990269:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[643:643:0419/114716.849480:12425990363:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[643:643:0419/114716.849561:12425990446:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.849649:12425990533:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0\n[643:643:0419/114716.849735:12425990619:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0\n[643:643:0419/114716.849817:12425990704:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.849915:12425990799:INFO:recurring-task.cc(55)] [Startup] Scheduling 8456 with a delay 0, Now = 210919424\n[643:643:0419/114716.849998:12425990881:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[643:643:0419/114716.850081:12425990966:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[643:643:0419/114716.850249:12425991131:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4300575850488581878\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.850362:12425991251:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8072 with a delay 500000, Now = 210919424\n[643:643:0419/114716.850451:12425991332:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 500\n[643:643:0419/114716.850534:12425991416:INFO:recurring-task.cc(55)] [Retry] Scheduling 8456 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.850618:12425991501:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000db0 with delay 60000\n[643:643:0419/114716.850707:12425991593:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0\n[643:643:0419/114716.850793:12425991680:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.850900:12425991783:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.851289:12425992173: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: \"4300575850488581878\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.851546:12425992436:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000af0 with delay 0\n[643:643:0419/114716.851641:12425992526:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0\n[643:643:0419/114716.851946:12425992829:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4300575850488581878\" 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[643:643:0419/114716.852065:12425992950:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4300575850488581878\"\n[643:643:0419/114716.852155:12425993036:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.852250:12425993132:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.852337:12425993220:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e00 with delay 1200000\n[643:643:0419/114716.852439:12425993321:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.852702:12425993588:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.852800:12425993693:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[643:643:0419/114716.852891:12425993778:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ad0 with delay 0\n[643:643:0419/114716.853025:12425993910: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[643:643:0419/114716.853126:12425994009:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ad0\n[643:643:0419/114716.853274:12425994159:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a30 with delay 0\n[643:643:0419/114716.853389:12425994271:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.853475:12425994357:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e10 with delay 10000\n[643:643:0419/114716.853559:12425994440:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a30\n[643:643:0419/114716.853637:12425994520:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.853736:12425994620:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.853839:12425994721:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000a30 with delay 0\n[643:643:0419/114716.853922:12425994803:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000a30\n[643:643:0419/114716.854141:12425995024: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[643:643:0419/114716.854404:12425995289:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e10\n[643:643:0419/114716.855280:12425996164: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 (8 ms)\n[27/28] InvalidationClientImplTest.NoRegistrationSummary (8 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[643:643:0419/114716.856609:12425997493:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c70 with delay 0\n[643:643:0419/114716.856741:12425997624:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[643:643:0419/114716.857194:12425998075:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 0\n[643:643:0419/114716.857276:12425998156:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c70\n[643:643:0419/114716.857359:12425998247:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b50\n[643:643:0419/114716.857529:12425998409:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[643:643:0419/114716.857649:12425998531:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[643:643:0419/114716.857734:12425998613:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[643:643:0419/114716.857806:12425998690:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[643:643:0419/114716.857886:12425998767:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 0\n[643:643:0419/114716.857974:12425998854:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b50\n[643:643:0419/114716.858049:12425998928:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[643:643:0419/114716.858139:12425999019:INFO:recurring-task.cc(55)] [Startup] Scheduling 7784 with a delay 0, Now = 210919424\n[643:643:0419/114716.858218:12425999098:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[643:643:0419/114716.858291:12425999172:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[643:643:0419/114716.858467:12425999348:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3458728803249036219\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[643:643:0419/114716.858552:12425999432:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[643:643:0419/114716.858628:12425999508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 500\n[643:643:0419/114716.858703:12425999582:INFO:recurring-task.cc(55)] [Retry] Scheduling 7784 with a delay 60000000, Now = 210919424\n[643:643:0419/114716.858782:12425999665:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000aa0 with delay 60000\n[643:643:0419/114716.858867:12425999748:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b50\n[643:643:0419/114716.858941:12425999822:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.859033:12425999912:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[643:643:0419/114716.859401:12426000283: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: \"-3458728803249036219\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[643:643:0419/114716.859611:12426000493:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b50 with delay 0\n[643:643:0419/114716.859691:12426000573:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b50\n[643:643:0419/114716.859995:12426000878:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3458728803249036219\" 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[643:643:0419/114716.860108:12426000988:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3458728803249036219\"\n[643:643:0419/114716.860189:12426001073:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[643:643:0419/114716.860277:12426001156:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[643:643:0419/114716.860358:12426001250:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a30 with delay 1200000\n[643:643:0419/114716.860451:12426001331:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[643:643:0419/114716.860716:12426001597:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.860802:12426001685:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[643:643:0419/114716.860884:12426001764:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ad0 with delay 0\n[643:643:0419/114716.861005:12426001885: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[643:643:0419/114716.861099:12426001980:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ad0\n[643:643:0419/114716.861239:12426002121:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000af0 with delay 0\n[643:643:0419/114716.861369:12426002269:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[643:643:0419/114716.861490:12426002371:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c70 with delay 10000\n[643:643:0419/114716.861570:12426002450:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0\n[643:643:0419/114716.861643:12426002524:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[643:643:0419/114716.861865:12426002744:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000c70\n[643:643:0419/114716.862482:12426003361:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400000aa0\n[643:643:0419/114716.874742:12426015630:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7b0400000a30\n[643:643:0419/114716.874950:12426015832:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.875081:12426015961:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[643:643:0419/114716.875209:12426016091:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[643:643:0419/114716.875677:12426016558: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[643:643:0419/114716.875791:12426016671:INFO:recurring-task.cc(55)] [Send-info] Scheduling 8456 with a delay 500000, Now = 1411419424\n[643:643:0419/114716.875885:12426016766:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400000aa0 with delay 500\n[643:643:0419/114716.875971:12426016852:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[643:643:0419/114716.876050:12426016930:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400000c70 with delay 1200000\n[643:643:0419/114716.876149:12426017029:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7b0400000aa0\n[643:643:0419/114716.876225:12426017104:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.876385:12426017266:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[643:643:0419/114716.876465:12426017346:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[643:643:0419/114716.877015:12426017895: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 (23 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (23 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "f86a8ed893e26bf94a1d721613627b6d99b952a0", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "444fbe0a70bafa11", "server_versions": [ "4267-53b17d5" ], "started_ts": "2019-04-19T18:47:12.140592", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux TSan Tests", "buildnumber:37313", "cpu:x86-64", "data:1df153a0c952d94ea3bf9be026ef6c9d15e086aa", "gpu:none", "master:chromium.memory", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "pool:Chrome", "priority:25", "project:chromium", "purpose:CI", "purpose:luci", "purpose:post-commit", "service_account:none", "slavename:swarm323-c4", "spec_name:chromium.ci:Linux TSan Tests", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:b0a6cb78cd34832b49b843b36f65ec5a7a568a79", "user:None" ], "task_id": "44556dd486f2ab10" } ] }