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-67-h51v" ] }, { "key": "image", "value": [ "chrome-trusty-18091700-38cc06ee3ee" ] }, { "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": [ "4211-90dafba" ] }, { "key": "zone", "value": [ "us", "us-east", "us-east1", "us-east1-b" ] } ], "bot_id": "chrome-trusty-67-h51v", "bot_version": "a1949c9c9626232734f8c6a011db49db86c0d07bdcf5444a07f04046abeaa3cd", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "nFftZl2kFquaI2EUmPGwzbc5sIbCocl9L55UeASqlLsC" }, "packages": [ { "package_name": "infra/python/cpython/linux-amd64", "path": ".swarming_module", "version": "46c0c897ca0f053799ee41fd148bb7a47232df47" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": ".swarming_module", "version": "2737ea8ed9b958f4d5aa9ffe106115a649ada241" }, { "package_name": "infra/tools/luci/vpython-native/linux-amd64", "path": ".swarming_module", "version": "OAXVAmcUSrvDygYUrCDzv20LRono9938YOHPu0zKowgC" }, { "package_name": "infra/tools/luci/vpython/linux-amd64", "path": ".swarming_module", "version": "ucaOciwAE9aweCUDOrmSvyiwrjmbywuB0NzAGUXIHjAC" } ] }, "completed_ts": "2019-03-21T00:31:01.282133", "costs_usd": [ 0.0008604872806726799 ], "created_ts": "2019-03-21T00:30:53.524028", "duration": 0.9765980243682861, "modified_ts": "2019-03-21T00:31:01.282133", "name": "cacheinvalidation_unittests/Ubuntu-14.04/1f0f1a9195/Linux MSan Tests/15685", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n MSAN_OPTIONS=symbolize=0 handle_abort=1\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioz5JNcZ/output.json\n\nIMPORTANT DEBUGGING NOTE: batches of tests are run inside their\nown process. For debugging a test inside a debugger, use the\n--gtest_filter=<your_test_name> flag along with\n--single-process-tests.\nUsing sharding settings from environment. This is shard 0/1\nUsing 8 parallel jobs.\n[ RUN ] ProtocolHandlerTest.TokenMissing\n[32528:32528:0320/173059.768890:5194207938:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0\n[32528:32528:0320/173059.769011:5194208055:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80\n[32528:32528:0320/173059.769378:5194208418: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[32528:32528:0320/173059.769444:5194208483:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424\n[32528:32528:0320/173059.769488:5194208525:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 500\n[32528:32528:0320/173059.769554:5194208591:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b90\n[32528:32528:0320/173059.769660:5194208698:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[32528:32528:0320/173059.769708:5194208748:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (1 ms)\n[1/28] ProtocolHandlerTest.TokenMissing (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[32528:32528:0320/173059.770283:5194209321:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 0\n[32528:32528:0320/173059.770331:5194209369:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b90\n[32528:32528:0320/173059.770383:5194209423:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424\n[32528:32528:0320/173059.770437:5194209478:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 500\n[32528:32528:0320/173059.770494:5194209538:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b80\n[32528:32528:0320/173059.770619:5194209658:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[32528:32528:0320/173059.770707:5194209745: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[32528:32528:0320/173059.770783:5194209821: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[32528:32528:0320/173059.770948:5194209986: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[32528:32528:0320/173059.771097:5194210135: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 (1 ms)\n[2/28] ProtocolHandlerTest.InvalidOutboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[32528:32528:0320/173059.771597:5194210636:INFO:protocol-handler.cc(139)] Incoming message: { }\n[32528:32528:0320/173059.771648:5194210687:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[32528:32528:0320/173059.771690:5194210729:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms)\n[3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[32528:32528:0320/173059.771972:5194211010:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1753630824 with a delay 10000, Now = 0\n[32528:32528:0320/173059.772021:5194211059:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10\n[32528:32528:0320/173059.772072:5194211111:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0\n[32528:32528:0320/173059.772113:5194211151:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[32528:32528:0320/173059.772159:5194211200:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630824 with a delay 60000, Now = 10000\n[32528:32528:0320/173059.772203:5194211243:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000a00 with delay 60\n[32528:32528:0320/173059.772253:5194211295:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x701000000a00\n[32528:32528:0320/173059.772294:5194211330:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[32528:32528:0320/173059.772331:5194211367:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630824 with a delay 60000, Now = 70000\n[32528:32528:0320/173059.772364:5194211400:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000009f0 with delay 60\n[32528:32528:0320/173059.772399:5194211435:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000009f0\n[32528:32528:0320/173059.772432:5194211468:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[32528:32528:0320/173059.772465:5194211500:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630824 with a delay 60000, Now = 130000\n[32528:32528:0320/173059.772497:5194211533:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x701000000a00 with delay 60\n[32528:32528:0320/173059.772531:5194211567:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x701000000a00\n[32528:32528:0320/173059.772563:5194211599:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[32528:32528:0320/173059.772596:5194211632:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630824 with a delay 60000, Now = 190000\n[32528:32528:0320/173059.772629:5194211665:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000009f0 with delay 60\n[32528:32528:0320/173059.772663:5194211699:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000009f0\n[32528:32528:0320/173059.772695:5194211731:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[32528:32528:0320/173059.772727:5194211763:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630824 with a delay 60000, Now = 250000\n[32528:32528:0320/173059.772762:5194211799:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x701000000a00 with delay 60\n[32528:32528:0320/173059.772798:5194211833:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x701000000a00\n[32528:32528:0320/173059.772829:5194211865:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[32528:32528:0320/173059.772862:5194211897:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630824 with a delay 60000, Now = 310000\n[32528:32528:0320/173059.772894:5194211930:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000009f0 with delay 60\n[32528:32528:0320/173059.772937:5194211973:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000009f0\n[32528:32528:0320/173059.772970:5194212022:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[32528:32528:0320/173059.773026:5194212062:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630824 with a delay 60000, Now = 370000\n[32528:32528:0320/173059.773059:5194212095:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x701000000a00 with delay 60\n[32528:32528:0320/173059.773094:5194212134:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x701000000a00\n[32528:32528:0320/173059.773135:5194212172: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[32528:32528:0320/173059.774421:5194213462:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1753630640 with a delay 10000, Now = 0\n[32528:32528:0320/173059.774465:5194213503:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000a00 with delay 10\n[32528:32528:0320/173059.774510:5194213547:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000a00\n[32528:32528:0320/173059.774553:5194213591:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[32528:32528:0320/173059.774604:5194213642:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630640 with a delay 50000, Now = 10000\n[32528:32528:0320/173059.774653:5194213691:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 50\n[32528:32528:0320/173059.774704:5194213741:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000009f0\n[32528:32528:0320/173059.774740:5194213779:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[32528:32528:0320/173059.774781:5194213818:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630640 with a delay 149000, Now = 60000\n[32528:32528:0320/173059.774820:5194213858:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x701000000a00 with delay 149\n[32528:32528:0320/173059.774864:5194213901:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x701000000a00\n[32528:32528:0320/173059.774910:5194213947:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[32528:32528:0320/173059.774964:5194214001:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630640 with a delay 248000, Now = 210000\n[32528:32528:0320/173059.775003:5194214044:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000009f0 with delay 248\n[32528:32528:0320/173059.775060:5194214105:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000009f0\n[32528:32528:0320/173059.775106:5194214144:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[32528:32528:0320/173059.775145:5194214182:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630640 with a delay 446000, Now = 460000\n[32528:32528:0320/173059.775183:5194214220:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x701000000a00 with delay 446\n[32528:32528:0320/173059.775241:5194214278:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x701000000a00\n[32528:32528:0320/173059.775285:5194214325:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[32528:32528:0320/173059.775323:5194214365:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630640 with a delay 842000, Now = 910000\n[32528:32528:0320/173059.775365:5194214402:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000009f0 with delay 842\n[32528:32528:0320/173059.775422:5194214458:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000009f0\n[32528:32528:0320/173059.775455:5194214491:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[32528:32528:0320/173059.775487:5194214523:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630640 with a delay 1040000, Now = 1760000\n[32528:32528:0320/173059.775521:5194214557:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x701000000a00 with delay 1040\n[32528:32528:0320/173059.775577:5194214613:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x701000000a00\n[32528:32528:0320/173059.775608:5194214644:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[32528:32528:0320/173059.775647:5194214683:INFO:recurring-task.cc(55)] [Retry] Scheduling 1753630640 with a delay 1040000, Now = 2800000\n[32528:32528:0320/173059.775680:5194214716:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000009f0 with delay 1040\n[32528:32528:0320/173059.775737:5194214773:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000009f0\n[32528:32528:0320/173059.775770:5194214806:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms)\n[5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[32528:32528:0320/173059.776944:5194215986:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1753630680 with a delay 10000, Now = 0\n[32528:32528:0320/173059.777014:5194216052:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10\n[32528:32528:0320/173059.777062:5194216100:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0\n[32528:32528:0320/173059.777102:5194216140:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[32528:32528:0320/173059.777143:5194216181:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1753630680 with a delay 10000, Now = 10000\n[32528:32528:0320/173059.777187:5194216230:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 10\n[32528:32528:0320/173059.777247:5194216292:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000009f0\n[32528:32528:0320/173059.777291:5194216328:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (2 ms)\n[6/28] RecurringTaskTest.OneShotTask (2 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[32528:32528:0320/173059.778606:5194217645:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000009f0 with delay 920\n[32528:32528:0320/173059.778673:5194217711:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.779036:5194218073:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000009f0 with delay 45000\n[32528:32528:0320/173059.780130:5194219169:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009f0\n[ OK ] ThrottleTest.ThrottlingScripted (2 ms)\n[7/28] ThrottleTest.ThrottlingScripted (2 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[32528:32528:0320/173059.780337:5194219374:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 990\n[32528:32528:0320/173059.780407:5194219445:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.780447:5194219483:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.780509:5194219544:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.780542:5194219578:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.780603:5194219638:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.780636:5194219671:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.780696:5194219731:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.780729:5194219764:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.780803:5194219839:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.780838:5194219873:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.780898:5194219934:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.780941:5194219978:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x701000000a00 with delay 54000\n[32528:32528:0320/173059.782627:5194221663:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000000a00\n[32528:32528:0320/173059.782675:5194221711:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.782737:5194221773:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x701000000a00\n[32528:32528:0320/173059.782773:5194221809:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.782835:5194221870:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x701000000a00\n[32528:32528:0320/173059.782869:5194221904:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.782937:5194221972:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x701000000a00\n[32528:32528:0320/173059.782972:5194222007:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.783032:5194222068:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x701000000a00\n[32528:32528:0320/173059.783066:5194222101:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.783126:5194222162:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x701000000a00\n[32528:32528:0320/173059.783160:5194222196:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.783224:5194222259:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x701000000a00\n[32528:32528:0320/173059.783257:5194222298:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000009f0 with delay 54000\n[32528:32528:0320/173059.784921:5194223965:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.784970:5194224022:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.785050:5194224086:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.785084:5194224120:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.785146:5194224182:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.785179:5194224215:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.785240:5194224275:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.785278:5194224314:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.785338:5194224374:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.785372:5194224407:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.785433:5194224468:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.785466:5194224501:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.785526:5194224562:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.785560:5194224596:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x701000000a00 with delay 54000\n[32528:32528:0320/173059.787195:5194226231:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x701000000a00\n[32528:32528:0320/173059.787232:5194226268:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.787297:5194226332:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x701000000a00\n[32528:32528:0320/173059.787331:5194226366:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.787397:5194226432:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x701000000a00\n[32528:32528:0320/173059.787433:5194226468:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.787494:5194226529:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x701000000a00\n[32528:32528:0320/173059.787527:5194226562:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.787587:5194226623:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x701000000a00\n[32528:32528:0320/173059.787621:5194226657:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.787681:5194226717:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x701000000a00\n[32528:32528:0320/173059.787714:5194226750:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x701000000a00 with delay 1000\n[32528:32528:0320/173059.787777:5194226812:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x701000000a00\n[32528:32528:0320/173059.787810:5194226846:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000009f0 with delay 54000\n[32528:32528:0320/173059.789460:5194228497:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.789504:5194228539:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.789564:5194228600:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.789598:5194228633:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.789658:5194228694:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.789692:5194228727:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.789752:5194228790:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.789787:5194228823:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.789847:5194228883:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.789880:5194228915:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.789948:5194228983:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.789982:5194229017:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000009f0 with delay 1000\n[32528:32528:0320/173059.790042:5194229078:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000009f0\n[32528:32528:0320/173059.790076:5194229112:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x701000000a00 with delay 54000\n[32528:32528:0320/173059.791711:5194230746:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x701000000a00\n[ OK ] ThrottleTest.ThrottlingStorm (11 ms)\n[8/28] ThrottleTest.ThrottlingStorm (11 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[32525:32525:0320/173059.749154:5194188196:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0\n[32525:32525:0320/173059.749565:5194188618:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80\n[32525:32525:0320/173059.749956:5194188994: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[32525:32525:0320/173059.750028:5194189077:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424\n[32525:32525:0320/173059.750089:5194189127:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 500\n[32525:32525:0320/173059.750143:5194189183:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10\n[32525:32525:0320/173059.750457:5194189510: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 (3 ms)\n[9/28] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[32525:32525:0320/173059.751773:5194190813: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[32525:32525:0320/173059.752325:5194191370:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[32525:32525:0320/173059.752406:5194191449:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b40 with delay 0\n[32525:32525:0320/173059.752462:5194191505:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0\n[32525:32525:0320/173059.752547:5194191591:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b00 with delay 0\n[32525:32525:0320/173059.752604:5194191639:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ab0 with delay 0\n[32525:32525:0320/173059.752652:5194191696:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[32525:32525:0320/173059.753140:5194192196:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[32525:32525:0320/173059.753312:5194192350: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[32525:32525:0320/173059.753378:5194192422:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424\n[32525:32525:0320/173059.753427:5194192477:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c60 with delay 500\n[32525:32525:0320/173059.753491:5194192527:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b40\n[32525:32525:0320/173059.753536:5194192571:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0\n[32525:32525:0320/173059.753571:5194192607:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b00\n[32525:32525:0320/173059.753618:5194192654:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ab0\n[32525:32525:0320/173059.753656:5194192692:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[32525:32525:0320/173059.753718:5194192761:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[32525:32525:0320/173059.753787:5194192836:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c60\n[32525:32525:0320/173059.753998:5194193035:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[32525:32525:0320/173059.755366:5194194421: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 (4 ms)\n[11/28] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[32525:32525:0320/173059.757264:5194196320:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } invalidation_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[12/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[32525:32525:0320/173059.757981:5194197025: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[32525:32525:0320/173059.758080:5194197124: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[32525:32525:0320/173059.758190:5194197234: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[32525:32525:0320/173059.758299:5194197347:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[13/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[32525:32525:0320/173059.758841:5194197882: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[32525:32525:0320/173059.758978:5194198016:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[14/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[32525:32525:0320/173059.759483:5194198537: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 (0 ms)\n[15/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[32525:32525:0320/173059.760053:5194199106: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[32525:32525:0320/173059.760146:5194199185:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a40 with delay 0\n[32525:32525:0320/173059.760192:5194199236:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a40\n[32525:32525:0320/173059.760292:5194199335: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[32525:32525:0320/173059.760354:5194199394:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424\n[32525:32525:0320/173059.760396:5194199435:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a50 with delay 500\n[32525:32525:0320/173059.760452:5194199495:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[32525:32525:0320/173059.760503:5194199540:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (46 ms)\n[16/28] ProtocolHandlerTest.ConfigMessage (46 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[32525:32525:0320/173059.805979:5194245023: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 (1 ms)\n[17/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[32525:32525:0320/173059.806525:5194245563: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 (0 ms)\n[18/28] ProtocolHandlerTest.TokenMismatch (0 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[32524:32524:0320/173059.743889:5194182934:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c80 with delay 0\n[32524:32524:0320/173059.744293:5194183338:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.744690:5194183736:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[32524:32524:0320/173059.744749:5194183789:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c80\n[32524:32524:0320/173059.744808:5194183844:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[32524:32524:0320/173059.744952:5194183998:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.745095:5194184135:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0\n[32524:32524:0320/173059.745164:5194184200:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0\n[32524:32524:0320/173059.745201:5194184245:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.745258:5194184297:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[32524:32524:0320/173059.745322:5194184358:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[32524:32524:0320/173059.745369:5194184411:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.745421:5194184466:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.745478:5194184517:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0\n[32524:32524:0320/173059.745524:5194184560:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0\n[32524:32524:0320/173059.745626:5194184665:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1395793862926238964\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.745681:5194184731:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.745737:5194184775:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 500\n[32524:32524:0320/173059.745778:5194184816:INFO:recurring-task.cc(55)] [Retry] Scheduling 9224 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.745818:5194184861:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e10 with delay 60000\n[32524:32524:0320/173059.745883:5194184947:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[32524:32524:0320/173059.745977:5194185016:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.746075:5194185130:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.746276:5194185317: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: \"-1395793862926238964\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.746526:5194185565:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e50 with delay 0\n[32524:32524:0320/173059.746572:5194185645:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[32524:32524:0320/173059.746776:5194185820:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1395793862926238964\" 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[32524:32524:0320/173059.746871:5194185910:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1395793862926238964\"\n[32524:32524:0320/173059.746945:5194185983:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.746997:5194186035:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.747046:5194186085:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e90 with delay 1200000\n[32524:32524:0320/173059.747109:5194186153:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.747318:5194186357:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.747368:5194186405:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.747423:5194186467:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ea0 with delay 0\n[32524:32524:0320/173059.747523:5194186561: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[32524:32524:0320/173059.747583:5194186623:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ea0\n[32524:32524:0320/173059.747686:5194186725:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 0\n[32524:32524:0320/173059.747748:5194186786:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.747793:5194186831:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c80 with delay 10000\n[32524:32524:0320/173059.747836:5194186872:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0\n[32524:32524:0320/173059.747871:5194186916:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (6 ms)\n[19/28] InvalidationClientImplTest.Start (6 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[32524:32524:0320/173059.748755:5194187796:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[32524:32524:0320/173059.748827:5194187864:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)\n[20/28] InvalidationClientImplTest.GenerateNonce (1 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[32524:32524:0320/173059.749456:5194188494:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0\n[32524:32524:0320/173059.749520:5194188557:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.749865:5194188912:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0\n[32524:32524:0320/173059.749949:5194188991:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80\n[32524:32524:0320/173059.750004:5194189041:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0\n[32524:32524:0320/173059.750087:5194189136:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.750185:5194189224:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[32524:32524:0320/173059.750239:5194189275:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[32524:32524:0320/173059.750274:5194189312:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.750319:5194189362:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0\n[32524:32524:0320/173059.750374:5194189410:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0\n[32524:32524:0320/173059.750410:5194189454:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.750462:5194189502:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.750515:5194189555:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[32524:32524:0320/173059.750559:5194189596:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[32524:32524:0320/173059.750647:5194189685:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4402975450439503839\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.750696:5194189745:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9224 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.750765:5194189812:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 500\n[32524:32524:0320/173059.750823:5194189871:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.750876:5194189920:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 60000\n[32524:32524:0320/173059.750952:5194189999:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0\n[32524:32524:0320/173059.751006:5194190050:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.751075:5194190118:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.751234:5194190274: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: \"4402975450439503839\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.751379:5194190417:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 0\n[32524:32524:0320/173059.751424:5194190472:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0\n[32524:32524:0320/173059.751601:5194190639:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4402975450439503839\" 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[32524:32524:0320/173059.751674:5194190724:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4402975450439503839\"\n[32524:32524:0320/173059.751730:5194190771:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.751776:5194190814:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.751818:5194190856:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f10 with delay 1200000\n[32524:32524:0320/173059.751866:5194190904:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.752061:5194191121:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.752146:5194191201:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.752216:5194191255:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[32524:32524:0320/173059.752288:5194191336: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[32524:32524:0320/173059.752353:5194191390:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[32524:32524:0320/173059.752429:5194191466:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0\n[32524:32524:0320/173059.752486:5194191524:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.752537:5194191582:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e80 with delay 10000\n[32524:32524:0320/173059.752585:5194191624:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40\n[32524:32524:0320/173059.752627:5194191665:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.752724:5194191767:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f40 with delay 0\n[32524:32524:0320/173059.752787:5194191843:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f40\n[32524:32524:0320/173059.752868:5194191911:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[32524:32524:0320/173059.752924:5194191970:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[32524:32524:0320/173059.752993:5194192030:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[32524:32524:0320/173059.753085:5194192129:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9224 with a delay 500000, Now = 211469424\n[32524:32524:0320/173059.753139:5194192187:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500\n[32524:32524:0320/173059.753197:5194192241:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424\n[32524:32524:0320/173059.753253:5194192296:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f30 with delay 60000\n[32524:32524:0320/173059.753320:5194192359:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[32524:32524:0320/173059.753376:5194192415:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.753435:5194192477:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.753479:5194192520:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[32524:32524:0320/173059.753668:5194192710: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[32524:32524:0320/173059.753793:5194192837:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.753906:5194192950:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f20 with delay 0\n[32524:32524:0320/173059.753974:5194193018:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[32524:32524:0320/173059.754248:5194193293: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[32524:32524:0320/173059.754374:5194193415: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[32524:32524:0320/173059.754477:5194193522:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[32524:32524:0320/173059.754630:5194193667:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[32524:32524:0320/173059.754720:5194193756:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[32524:32524:0320/173059.755033:5194194076:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e80\n[ OK ] InvalidationClientImplTest.Register (7 ms)\n[21/28] InvalidationClientImplTest.Register (7 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[32524:32524:0320/173059.756749:5194195788:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dc0 with delay 0\n[32524:32524:0320/173059.756816:5194195853:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.757241:5194196289:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0\n[32524:32524:0320/173059.757302:5194196349:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000dc0\n[32524:32524:0320/173059.757355:5194196392:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30\n[32524:32524:0320/173059.757429:5194196468:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.757501:5194196539:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0\n[32524:32524:0320/173059.757552:5194196589:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40\n[32524:32524:0320/173059.757594:5194196639:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.757649:5194196692:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0\n[32524:32524:0320/173059.757706:5194196743:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30\n[32524:32524:0320/173059.757748:5194196787:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.757801:5194196846:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.757849:5194196892:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0\n[32524:32524:0320/173059.757893:5194196929:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40\n[32524:32524:0320/173059.757975:5194197024:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-5307333758006701884\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.758044:5194197083:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.758086:5194197129:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 500\n[32524:32524:0320/173059.758140:5194197184:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.758194:5194197232:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ba0 with delay 60000\n[32524:32524:0320/173059.758247:5194197286:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30\n[32524:32524:0320/173059.758287:5194197328:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.758341:5194197379:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.758487:5194197531: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: \"-5307333758006701884\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.758627:5194197666:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c30 with delay 0\n[32524:32524:0320/173059.758674:5194197712:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30\n[32524:32524:0320/173059.758817:5194197856:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-5307333758006701884\" 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[32524:32524:0320/173059.758893:5194197932:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-5307333758006701884\"\n[32524:32524:0320/173059.758947:5194197991:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.759003:5194198056:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.759061:5194198112:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000\n[32524:32524:0320/173059.759134:5194198172:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.759279:5194198326:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.759333:5194198379:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.759395:5194198435:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0\n[32524:32524:0320/173059.759461:5194198500: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[32524:32524:0320/173059.759511:5194198548:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40\n[32524:32524:0320/173059.759587:5194198627:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f70 with delay 0\n[32524:32524:0320/173059.759638:5194198675:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.759678:5194198723:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000dc0 with delay 10000\n[32524:32524:0320/173059.759736:5194198772:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f70\n[32524:32524:0320/173059.759773:5194198811:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.759841:5194198883:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.759914:5194198961:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 0\n[32524:32524:0320/173059.759966:5194199004:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f70\n[32524:32524:0320/173059.760203:5194199245: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[32524:32524:0320/173059.760310:5194199354: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[32524:32524:0320/173059.760408:5194199446: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[32524:32524:0320/173059.760555:5194199592: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[32524:32524:0320/173059.760655:5194199693: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[32524:32524:0320/173059.760749:5194199797:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f70 with delay 0\n[32524:32524:0320/173059.760805:5194199849:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f40 with delay 0\n[32524:32524:0320/173059.760859:5194199896:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f50 with delay 0\n[32524:32524:0320/173059.760901:5194199940:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f70\n[32524:32524:0320/173059.760970:5194200025:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424\n[32524:32524:0320/173059.761027:5194200068:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000c30 with delay 500\n[32524:32524:0320/173059.761085:5194200127:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f40\n[32524:32524:0320/173059.761135:5194200171:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f50\n[32524:32524:0320/173059.761188:5194200227:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000000c30\n[32524:32524:0320/173059.761228:5194200268:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.761288:5194200326:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.761334:5194200372:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[32524:32524:0320/173059.761535:5194200576: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 (5 ms)\n[22/28] InvalidationClientImplTest.Invalidations (5 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[32524:32524:0320/173059.762371:5194201410:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000eb0 with delay 0\n[32524:32524:0320/173059.762437:5194201474:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.762681:5194201726:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[32524:32524:0320/173059.762738:5194201776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000eb0\n[32524:32524:0320/173059.762780:5194201816:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[32524:32524:0320/173059.762851:5194201900:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.762950:5194201988:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[32524:32524:0320/173059.762998:5194202035:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[32524:32524:0320/173059.763033:5194202075:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.763076:5194202123:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[32524:32524:0320/173059.763125:5194202161:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[32524:32524:0320/173059.763160:5194202198:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.763206:5194202244:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.763247:5194202285:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[32524:32524:0320/173059.763288:5194202324:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[32524:32524:0320/173059.763359:5194202403:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2173692396375833547\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.763411:5194202452:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.763458:5194202498:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500\n[32524:32524:0320/173059.763499:5194202548:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.763556:5194202594:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d40 with delay 60000\n[32524:32524:0320/173059.763617:5194202656:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[32524:32524:0320/173059.763663:5194202701:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.763715:5194202753:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.763860:5194202898: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: \"2173692396375833547\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.763994:5194203037:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0\n[32524:32524:0320/173059.764055:5194203099:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[32524:32524:0320/173059.764202:5194203248:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2173692396375833547\" 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[32524:32524:0320/173059.764272:5194203310:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2173692396375833547\"\n[32524:32524:0320/173059.764316:5194203354:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.764361:5194203399:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.764402:5194203440:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 1200000\n[32524:32524:0320/173059.764446:5194203484:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.764578:5194203624:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.764645:5194203688:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.764702:5194203746:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[32524:32524:0320/173059.764771:5194203809: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[32524:32524:0320/173059.764821:5194203857:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[32524:32524:0320/173059.764895:5194203932:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 0\n[32524:32524:0320/173059.764960:5194204018:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.765022:5194204066:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000eb0 with delay 10000\n[32524:32524:0320/173059.765066:5194204103:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c20\n[32524:32524:0320/173059.765110:5194204154:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.765180:5194204223:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.765248:5194204287:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000c20 with delay 0\n[32524:32524:0320/173059.765290:5194204328:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000c20\n[32524:32524:0320/173059.765435:5194204478: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[32524:32524:0320/173059.765528:5194204570: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[32524:32524:0320/173059.765582:5194204623:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[32524:32524:0320/173059.765629:5194204672:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424\n[32524:32524:0320/173059.765685:5194204724:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500\n[32524:32524:0320/173059.765740:5194204783:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[32524:32524:0320/173059.766007:5194205046: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[32524:32524:0320/173059.766088:5194205136:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[32524:32524:0320/173059.766142:5194205191:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.766242:5194205281:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.766288:5194205332:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[32524:32524:0320/173059.768075:5194207124: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[32524:32524:0320/173059.768447:5194207485:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000eb0\n[ OK ] InvalidationClientImplTest.ServerRequests (7 ms)\n[23/28] InvalidationClientImplTest.ServerRequests (7 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[32524:32524:0320/173059.770195:5194209235:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[32524:32524:0320/173059.770264:5194209301:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.770529:5194209568:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[32524:32524:0320/173059.770577:5194209625:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[32524:32524:0320/173059.770639:5194209676:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[32524:32524:0320/173059.770710:5194209757:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.770794:5194209837:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0\n[32524:32524:0320/173059.770854:5194209890:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0\n[32524:32524:0320/173059.770889:5194209927:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.770941:5194209979:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[32524:32524:0320/173059.770980:5194210016:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[32524:32524:0320/173059.771015:5194210064:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.771072:5194210122:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.771130:5194210168:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0\n[32524:32524:0320/173059.771181:5194210217:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0\n[32524:32524:0320/173059.771257:5194210295:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7732066062137048998\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.771302:5194210346:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.771354:5194210398:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500\n[32524:32524:0320/173059.771408:5194210448:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.771449:5194210488:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 60000\n[32524:32524:0320/173059.771510:5194210549:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[32524:32524:0320/173059.771556:5194210594:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.771609:5194210652:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.771761:5194210803: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: \"-7732066062137048998\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.771905:5194210944:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0\n[32524:32524:0320/173059.771959:5194211006:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[32524:32524:0320/173059.772109:5194211148:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7732066062137048998\" 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[32524:32524:0320/173059.772174:5194211221:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7732066062137048998\"\n[32524:32524:0320/173059.772232:5194211270:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.772279:5194211323:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.772332:5194211370:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 1200000\n[32524:32524:0320/173059.772379:5194211417:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.772522:5194211566:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.772581:5194211621:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.772626:5194211665:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ae0 with delay 0\n[32524:32524:0320/173059.772689:5194211732: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[32524:32524:0320/173059.772745:5194211781:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ae0\n[32524:32524:0320/173059.772819:5194211856:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000009e0 with delay 0\n[32524:32524:0320/173059.772868:5194211906:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.772911:5194211949:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 10000\n[32524:32524:0320/173059.772959:5194211995:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000009e0\n[32524:32524:0320/173059.773017:5194212058:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.773095:5194212133:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.773154:5194212202:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000009e0 with delay 0\n[32524:32524:0320/173059.773207:5194212245:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000009e0\n[32524:32524:0320/173059.773333:5194212372: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[32524:32524:0320/173059.773415:5194212453: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[32524:32524:0320/173059.773465:5194212504:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[32524:32524:0320/173059.773783:5194212825:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000b50\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[24/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[32524:32524:0320/173059.775379:5194214419:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d90 with delay 0\n[32524:32524:0320/173059.775447:5194214484:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.775783:5194214823:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[32524:32524:0320/173059.775834:5194214879:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d90\n[32524:32524:0320/173059.775883:5194214919:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70\n[32524:32524:0320/173059.775969:5194215007:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.776042:5194215080:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0\n[32524:32524:0320/173059.776095:5194215131:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50\n[32524:32524:0320/173059.776130:5194215168:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.776172:5194215210:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[32524:32524:0320/173059.776213:5194215250:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70\n[32524:32524:0320/173059.776248:5194215286:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.776293:5194215337:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.776344:5194215383:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0\n[32524:32524:0320/173059.776383:5194215420:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50\n[32524:32524:0320/173059.776465:5194215506:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3056790631725522730\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.776514:5194215561:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.776564:5194215602:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 500\n[32524:32524:0320/173059.776609:5194215657:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.776664:5194215708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 60000\n[32524:32524:0320/173059.776727:5194215766:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70\n[32524:32524:0320/173059.776771:5194215813:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.776829:5194215868:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.776997:5194216035: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: \"-3056790631725522730\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.777135:5194216174:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e70 with delay 0\n[32524:32524:0320/173059.777180:5194216225:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70\n[32524:32524:0320/173059.777323:5194216361:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3056790631725522730\" 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[32524:32524:0320/173059.777396:5194216434:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3056790631725522730\"\n[32524:32524:0320/173059.777445:5194216484:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.777491:5194216529:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.777534:5194216575:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 1200000\n[32524:32524:0320/173059.777589:5194216643:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.777744:5194216786:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.777796:5194216834:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.777837:5194216881:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f50 with delay 0\n[32524:32524:0320/173059.777913:5194216951: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[32524:32524:0320/173059.777978:5194217015:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f50\n[32524:32524:0320/173059.778051:5194217088:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f60 with delay 0\n[32524:32524:0320/173059.778165:5194217203:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.778206:5194217244:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d90 with delay 10000\n[32524:32524:0320/173059.778256:5194217293:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f60\n[32524:32524:0320/173059.778292:5194217335:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.778372:5194217410:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f60 with delay 0\n[32524:32524:0320/173059.778413:5194217461:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f60\n[32524:32524:0320/173059.778481:5194217522:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[32524:32524:0320/173059.778551:5194217595:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424\n[32524:32524:0320/173059.778611:5194217660:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 500\n[32524:32524:0320/173059.778679:5194217717:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9224 with a delay 60000000, Now = 211469424\n[32524:32524:0320/173059.778723:5194217767:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 60000\n[32524:32524:0320/173059.778796:5194217834:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50\n[32524:32524:0320/173059.778840:5194217886:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.778903:5194217941:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.778955:5194217993:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[32524:32524:0320/173059.779111:5194218150: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[32524:32524:0320/173059.779225:5194218263:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.779286:5194218324:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f50 with delay 0\n[32524:32524:0320/173059.779328:5194218366:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50\n[32524:32524:0320/173059.779456:5194218498: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[32524:32524:0320/173059.779536:5194218582: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[32524:32524:0320/173059.779588:5194218633:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[32524:32524:0320/173059.779706:5194218744:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[32524:32524:0320/173059.780033:5194219072:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000d90\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms)\n[25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[32524:32524:0320/173059.781696:5194220736:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c20 with delay 0\n[32524:32524:0320/173059.781762:5194220800:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.782028:5194221069:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[32524:32524:0320/173059.782081:5194221125:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c20\n[32524:32524:0320/173059.782129:5194221165:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[32524:32524:0320/173059.782199:5194221238:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.782268:5194221306:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0\n[32524:32524:0320/173059.782314:5194221351:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20\n[32524:32524:0320/173059.782349:5194221395:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.782399:5194221440:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[32524:32524:0320/173059.782442:5194221478:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[32524:32524:0320/173059.782477:5194221516:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.782530:5194221568:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.782571:5194221617:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0\n[32524:32524:0320/173059.782626:5194221662:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20\n[32524:32524:0320/173059.782699:5194221737:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"420723520167120989\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.782743:5194221784:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.782785:5194221826:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 500\n[32524:32524:0320/173059.782826:5194221864:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.782873:5194221918:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c50 with delay 60000\n[32524:32524:0320/173059.782946:5194221985:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[32524:32524:0320/173059.782990:5194222033:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.783059:5194222103:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.783218:5194222257: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: \"420723520167120989\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.783342:5194222383:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 0\n[32524:32524:0320/173059.783386:5194222430:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[32524:32524:0320/173059.783533:5194222571:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"420723520167120989\" 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[32524:32524:0320/173059.783602:5194222640:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"420723520167120989\"\n[32524:32524:0320/173059.783653:5194222698:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.783707:5194222745:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.783749:5194222787:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000\n[32524:32524:0320/173059.783794:5194222832:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.783960:5194222998:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.784006:5194223045:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.784049:5194223100:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 0\n[32524:32524:0320/173059.784144:5194223187: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[32524:32524:0320/173059.784204:5194223241:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e20\n[32524:32524:0320/173059.784280:5194223318:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0\n[32524:32524:0320/173059.784326:5194223366:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.784367:5194223405:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 10000\n[32524:32524:0320/173059.784407:5194223443:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[32524:32524:0320/173059.784444:5194223488:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.784516:5194223554:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0\n[32524:32524:0320/173059.784558:5194223597:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50\n[32524:32524:0320/173059.784618:5194223656:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[32524:32524:0320/173059.784683:5194223721:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424\n[32524:32524:0320/173059.784732:5194223771:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000e20 with delay 500\n[32524:32524:0320/173059.784775:5194223813:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424\n[32524:32524:0320/173059.784816:5194223854:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000af0 with delay 60000\n[32524:32524:0320/173059.784885:5194223922:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000e20\n[32524:32524:0320/173059.784928:5194223976:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.785007:5194224045:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.785051:5194224089:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[32524:32524:0320/173059.785209:5194224247: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[32524:32524:0320/173059.785517:5194224563:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c20\n[32524:32524:0320/173059.786696:5194225732:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000c50\n[32524:32524:0320/173059.786744:5194225780:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000af0\n[32524:32524:0320/173059.786810:5194225849: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[32524:32524:0320/173059.786859:5194225897:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[32524:32524:0320/173059.786973:5194226016: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[32524:32524:0320/173059.787035:5194226073:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424\n[32524:32524:0320/173059.787078:5194226132:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c50 with delay 500\n[32524:32524:0320/173059.787140:5194226178:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424\n[32524:32524:0320/173059.787182:5194226221:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c20 with delay 60000\n[32524:32524:0320/173059.787233:5194226277:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000c50\n[32524:32524:0320/173059.787283:5194226321:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.787343:5194226385:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.787393:5194226431:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[32524:32524:0320/173059.787555:5194226593:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 1 registration_digest: \"\\327\\003\\047\\242\\324@\\3740-O\\354\\3229\\352\\000\\231\\340\\204\\224\\323\" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: \"3\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } server_registration_summary_requested: true } }\n[ OK ] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[26/28] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[32524:32524:0320/173059.789531:5194228571:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0\n[32524:32524:0320/173059.789603:5194228641:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.789836:5194228884:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[32524:32524:0320/173059.789900:5194228940:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30\n[32524:32524:0320/173059.789959:5194228996:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[32524:32524:0320/173059.790031:5194229073:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.790108:5194229146:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[32524:32524:0320/173059.790158:5194229194:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[32524:32524:0320/173059.790193:5194229231:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.790231:5194229272:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[32524:32524:0320/173059.790273:5194229310:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[32524:32524:0320/173059.790312:5194229354:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.790359:5194229397:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.790410:5194229454:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[32524:32524:0320/173059.790464:5194229501:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[32524:32524:0320/173059.790539:5194229578:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-5921124788833586748\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.790603:5194229641:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.790647:5194229685:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 500\n[32524:32524:0320/173059.790692:5194229739:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.790742:5194229789:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dd0 with delay 60000\n[32524:32524:0320/173059.790805:5194229844:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[32524:32524:0320/173059.790848:5194229892:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.790908:5194229968:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.791075:5194230125: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: \"-5921124788833586748\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.791219:5194230261:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0\n[32524:32524:0320/173059.791269:5194230316:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[32524:32524:0320/173059.791411:5194230451:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-5921124788833586748\" 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[32524:32524:0320/173059.791476:5194230514:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-5921124788833586748\"\n[32524:32524:0320/173059.791520:5194230564:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.791575:5194230614:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.791618:5194230656:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 1200000\n[32524:32524:0320/173059.791665:5194230703:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.791801:5194230839:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.791845:5194230883:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.791887:5194230931:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[32524:32524:0320/173059.791967:5194231006: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[32524:32524:0320/173059.792017:5194231054:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[32524:32524:0320/173059.792097:5194231135:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0\n[32524:32524:0320/173059.792146:5194231184:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.792189:5194231229:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e30 with delay 10000\n[32524:32524:0320/173059.792238:5194231274:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[32524:32524:0320/173059.792273:5194231314:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.792345:5194231383:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.792397:5194231435:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0\n[32524:32524:0320/173059.792439:5194231477:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50\n[32524:32524:0320/173059.792540:5194231584: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[32524:32524:0320/173059.792833:5194231872:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e30\n[32524:32524:0320/173059.793861:5194232900: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 (5 ms)\n[27/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[32524:32524:0320/173059.794542:5194233581:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c90 with delay 0\n[32524:32524:0320/173059.794609:5194233646:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[32524:32524:0320/173059.794867:5194233906:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0\n[32524:32524:0320/173059.794916:5194233965:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c90\n[32524:32524:0320/173059.794972:5194234008:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70\n[32524:32524:0320/173059.795042:5194234084:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[32524:32524:0320/173059.795115:5194234154:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[32524:32524:0320/173059.795162:5194234198:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[32524:32524:0320/173059.795199:5194234244:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[32524:32524:0320/173059.795250:5194234292:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0\n[32524:32524:0320/173059.795293:5194234330:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70\n[32524:32524:0320/173059.795329:5194234370:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[32524:32524:0320/173059.795374:5194234412:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424\n[32524:32524:0320/173059.795415:5194234459:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[32524:32524:0320/173059.795467:5194234503:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[32524:32524:0320/173059.795540:5194234585:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"5693456365285791950\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[32524:32524:0320/173059.795598:5194234636:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[32524:32524:0320/173059.795636:5194234681:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 500\n[32524:32524:0320/173059.795687:5194234728:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424\n[32524:32524:0320/173059.795728:5194234766:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 60000\n[32524:32524:0320/173059.795787:5194234826:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70\n[32524:32524:0320/173059.795830:5194234868:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.795883:5194234924:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[32524:32524:0320/173059.796036:5194235080: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: \"5693456365285791950\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[32524:32524:0320/173059.796172:5194235213:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b70 with delay 0\n[32524:32524:0320/173059.796216:5194235254:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70\n[32524:32524:0320/173059.796346:5194235386:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"5693456365285791950\" 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[32524:32524:0320/173059.796416:5194235454:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"5693456365285791950\"\n[32524:32524:0320/173059.796461:5194235499:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[32524:32524:0320/173059.796506:5194235544:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[32524:32524:0320/173059.796548:5194235593:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 1200000\n[32524:32524:0320/173059.796604:5194235642:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[32524:32524:0320/173059.796740:5194235778:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.796783:5194235821:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[32524:32524:0320/173059.796824:5194235862:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[32524:32524:0320/173059.796883:5194235921: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[32524:32524:0320/173059.796946:5194235982:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[32524:32524:0320/173059.797038:5194236075:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0\n[32524:32524:0320/173059.797085:5194236137:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[32524:32524:0320/173059.797138:5194236180:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c90 with delay 10000\n[32524:32524:0320/173059.797180:5194236216:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[32524:32524:0320/173059.797215:5194236253:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[32524:32524:0320/173059.797514:5194236553:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c90\n[32524:32524:0320/173059.798722:5194237759:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000ac0\n[32524:32524:0320/173059.825479:5194264521:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000a50\n[32524:32524:0320/173059.825574:5194264613:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.825662:5194264703:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[32524:32524:0320/173059.825713:5194264756:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[32524:32524:0320/173059.825967:5194265007: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[32524:32524:0320/173059.826041:5194265080:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424\n[32524:32524:0320/173059.826105:5194265151:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000ac0 with delay 500\n[32524:32524:0320/173059.826162:5194265209:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[32524:32524:0320/173059.826214:5194265256:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000c90 with delay 1200000\n[32524:32524:0320/173059.826271:5194265308:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000ac0\n[32524:32524:0320/173059.826310:5194265349:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.826399:5194265438:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[32524:32524:0320/173059.826439:5194265488:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[32524:32524:0320/173059.826704:5194265746:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: \"2\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } performance_counter: { name: \"SentMessageType.INITIALIZE\" value: 1 } performance_counter: { name: \"SentMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOKEN_CONTROL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ListenerEventType.REISSUE_REGISTRATIONS\" value: 1 } performance_counter: { name: \"ClientErrorType.PERSISTENT_READ_FAILURE\" value: 1 } server_registration_summary_requested: false } }\n[ OK ] InvalidationClientImplTest.Heartbeats (34 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (34 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "c51863948bb58762c27832ce2c2eb268257691ee", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43b679f06d5ae211", "server_versions": [ "4211-90dafba" ], "started_ts": "2019-03-21T00:30:54.360755", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux MSan Tests", "buildnumber:15685", "cpu:x86-64", "data:1f0f1a91956302f1dc23ecaf23e0ac67cfb1b10b", "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:swarm2372-c4", "spec_name:chromium.ci:Linux MSan Tests", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:b63ec0b45a6b93fc5873cabac4c1cc31cf2c62c2", "user:None" ], "task_id": "43b679f06d5ae210", "try_number": "1" } ] }