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": [ "gce-trusty-e833d7b0-us-west1-b-ztxj" ] }, { "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": [ "4004-c99644c" ] }, { "key": "zone", "value": [ "us", "us-west", "us-west1", "us-west1-b" ] } ], "bot_id": "gce-trusty-e833d7b0-us-west1-b-ztxj", "bot_version": "4fadc44f6e41f1590cfed449d5d3a03480413054a65bb7f943cb6b050b7c2cfc", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "a2dqpK39PjGpFdcdw62OAE0JOJJ9n8J_AXpJHmH0QCIC" }, "packages": [ { "package_name": "infra/python/cpython/linux-amd64", "path": ".swarming_module", "version": "46c0c897ca0f053799ee41fd148bb7a47232df47" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": ".swarming_module", "version": "2737ea8ed9b958f4d5aa9ffe106115a649ada241" }, { "package_name": "infra/tools/luci/vpython-native/linux-amd64", "path": ".swarming_module", "version": "OAXVAmcUSrvDygYUrCDzv20LRono9938YOHPu0zKowgC" }, { "package_name": "infra/tools/luci/vpython/linux-amd64", "path": ".swarming_module", "version": "ucaOciwAE9aweCUDOrmSvyiwrjmbywuB0NzAGUXIHjAC" } ] }, "completed_ts": "2019-01-20T21:10:51.768996", "costs_usd": [ 0.0008368682404656727 ], "created_ts": "2019-01-20T21:10:16.634027", "duration": 0.8222188949584961, "modified_ts": "2019-01-20T21:10:51.768996", "name": "cacheinvalidation_unittests/Ubuntu-14.04/b5c1d81c08/ToTLinuxASan/4770", "output": "Additional test environment:\n ASAN_OPTIONS=symbolize=0\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 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/ioK8AEBR/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[2902:2902:0120/131050.608497:6768081354:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d790 with delay 0\n[2902:2902:0120/131050.608578:6768081431:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d790\n[2902:2902:0120/131050.608886:6768081739: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[2902:2902:0120/131050.608953:6768081805:INFO:recurring-task.cc(55)] [Send-info] Scheduling 33064 with a delay 500000, Now = 210919424\n[2902:2902:0120/131050.608998:6768081851:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d7b0 with delay 500\n[2902:2902:0120/131050.609031:6768081883:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d7b0\n[2902:2902:0120/131050.609129:6768081982:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[2902:2902:0120/131050.609171:6768082023: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[2902:2902:0120/131050.609654:6768082507:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000dc90 with delay 0\n[2902:2902:0120/131050.609702:6768082555:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000dc90\n[2902:2902:0120/131050.609757:6768082613:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 37544 with a delay 500000, Now = 210919424\n[2902:2902:0120/131050.609795:6768082647:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000dcb0 with delay 500\n[2902:2902:0120/131050.609843:6768082695:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000dcb0\n[2902:2902:0120/131050.609963:6768082815:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[2902:2902:0120/131050.610026:6768082878: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[2902:2902:0120/131050.610099:6768082954: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[2902:2902:0120/131050.610256:6768083107: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[2902:2902:0120/131050.610425:6768083291: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[2902:2902:0120/131050.610912:6768083781:INFO:protocol-handler.cc(139)] Incoming message: { }\n[2902:2902:0120/131050.610972:6768083830:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[2902:2902:0120/131050.611010:6768083862:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[3/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[2902:2902:0120/131050.611301:6768084158:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -2143855512 with a delay 10000, Now = 0\n[2902:2902:0120/131050.611347:6768084199:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x60200000e290 with delay 10\n[2902:2902:0120/131050.611386:6768084239:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x60200000e290\n[2902:2902:0120/131050.611422:6768084286:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[2902:2902:0120/131050.611468:6768084320:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143855512 with a delay 60000, Now = 10000\n[2902:2902:0120/131050.611495:6768084348:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x60200000e2b0 with delay 60\n[2902:2902:0120/131050.611528:6768084380:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x60200000e2b0\n[2902:2902:0120/131050.611553:6768084405:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[2902:2902:0120/131050.611576:6768084427:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143855512 with a delay 60000, Now = 70000\n[2902:2902:0120/131050.611604:6768084455:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x60200000e2d0 with delay 60\n[2902:2902:0120/131050.611636:6768084487:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x60200000e2d0\n[2902:2902:0120/131050.611658:6768084511:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[2902:2902:0120/131050.611680:6768084530:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143855512 with a delay 60000, Now = 130000\n[2902:2902:0120/131050.611705:6768084555:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x60200000e2f0 with delay 60\n[2902:2902:0120/131050.611726:6768084577:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x60200000e2f0\n[2902:2902:0120/131050.611746:6768084596:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[2902:2902:0120/131050.611765:6768084615:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143855512 with a delay 60000, Now = 190000\n[2902:2902:0120/131050.611786:6768084635:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x60200000e310 with delay 60\n[2902:2902:0120/131050.611803:6768084653:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x60200000e310\n[2902:2902:0120/131050.611822:6768084672:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[2902:2902:0120/131050.611840:6768084689:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143855512 with a delay 60000, Now = 250000\n[2902:2902:0120/131050.611856:6768084706:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x60200000e330 with delay 60\n[2902:2902:0120/131050.611874:6768084724:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x60200000e330\n[2902:2902:0120/131050.611891:6768084740:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[2902:2902:0120/131050.611909:6768084770:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143855512 with a delay 60000, Now = 310000\n[2902:2902:0120/131050.611947:6768084799:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x60200000e350 with delay 60\n[2902:2902:0120/131050.611971:6768084822:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x60200000e350\n[2902:2902:0120/131050.611993:6768084843:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[2902:2902:0120/131050.612013:6768084864:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143855512 with a delay 60000, Now = 370000\n[2902:2902:0120/131050.612051:6768084904:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x60200000e370 with delay 60\n[2902:2902:0120/131050.612077:6768084927:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x60200000e370\n[2902:2902:0120/131050.612121:6768084973:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (1 ms)\n[4/28] RecurringTaskTest.PeriodicTask (1 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[2902:2902:0120/131050.612458:6768085313:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -2143813528 with a delay 10000, Now = 0\n[2902:2902:0120/131050.612497:6768085350:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x60200000e3f0 with delay 10\n[2902:2902:0120/131050.612536:6768085389:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x60200000e3f0\n[2902:2902:0120/131050.612562:6768085414:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[2902:2902:0120/131050.612606:6768085460:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143813528 with a delay 50000, Now = 10000\n[2902:2902:0120/131050.612635:6768085491:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x60200000e410 with delay 50\n[2902:2902:0120/131050.612683:6768085535:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x60200000e410\n[2902:2902:0120/131050.612716:6768085568:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[2902:2902:0120/131050.612741:6768085593:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143813528 with a delay 149000, Now = 60000\n[2902:2902:0120/131050.612775:6768085627:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x60200000e430 with delay 149\n[2902:2902:0120/131050.612809:6768085661:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x60200000e430\n[2902:2902:0120/131050.612847:6768085698:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[2902:2902:0120/131050.612878:6768085728:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143813528 with a delay 248000, Now = 210000\n[2902:2902:0120/131050.612924:6768085777:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x60200000e450 with delay 248\n[2902:2902:0120/131050.612955:6768085805:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x60200000e450\n[2902:2902:0120/131050.612981:6768085835:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[2902:2902:0120/131050.613010:6768085861:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143813528 with a delay 446000, Now = 460000\n[2902:2902:0120/131050.613042:6768085897:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x60200000e470 with delay 446\n[2902:2902:0120/131050.613080:6768085932:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x60200000e470\n[2902:2902:0120/131050.613109:6768085959:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[2902:2902:0120/131050.613138:6768085990:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143813528 with a delay 842000, Now = 910000\n[2902:2902:0120/131050.613169:6768086022:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x60200000e490 with delay 842\n[2902:2902:0120/131050.613198:6768086048:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x60200000e490\n[2902:2902:0120/131050.613216:6768086068:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[2902:2902:0120/131050.613237:6768086087:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143813528 with a delay 1040000, Now = 1760000\n[2902:2902:0120/131050.613259:6768086108:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x60200000e4b0 with delay 1040\n[2902:2902:0120/131050.613288:6768086138:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x60200000e4b0\n[2902:2902:0120/131050.613308:6768086160:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[2902:2902:0120/131050.613331:6768086180:INFO:recurring-task.cc(55)] [Retry] Scheduling -2143813528 with a delay 1040000, Now = 2800000\n[2902:2902:0120/131050.613369:6768086221:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x60200000e4d0 with delay 1040\n[2902:2902:0120/131050.613400:6768086250:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x60200000e4d0\n[2902:2902:0120/131050.613422:6768086271:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (1 ms)\n[5/28] RecurringTaskTest.ExponentialBackoffTask (1 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[2902:2902:0120/131050.613717:6768086570:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -2143771544 with a delay 10000, Now = 0\n[2902:2902:0120/131050.613759:6768086612:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x60200000e550 with delay 10\n[2902:2902:0120/131050.613794:6768086646:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x60200000e550\n[2902:2902:0120/131050.613827:6768086679:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[2902:2902:0120/131050.613859:6768086716:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -2143771544 with a delay 10000, Now = 10000\n[2902:2902:0120/131050.613900:6768086752:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x60200000e570 with delay 10\n[2902:2902:0120/131050.613948:6768086800:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x60200000e570\n[2902:2902:0120/131050.613983:6768086836:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (1 ms)\n[6/28] RecurringTaskTest.OneShotTask (1 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[2902:2902:0120/131050.614331:6768087185:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x60200000e5f0 with delay 920\n[2902:2902:0120/131050.614378:6768087235:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x60200000e5f0\n[2902:2902:0120/131050.614492:6768087345:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x60200000e610 with delay 45000\n[2902:2902:0120/131050.614687:6768087537:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x60200000e610\n[ OK ] ThrottleTest.ThrottlingScripted (0 ms)\n[7/28] ThrottleTest.ThrottlingScripted (0 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[2902:2902:0120/131050.614840:6768087691:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x60200000e690 with delay 990\n[2902:2902:0120/131050.614904:6768087754:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x60200000e690\n[2902:2902:0120/131050.614947:6768087798:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x60200000e6b0 with delay 1000\n[2902:2902:0120/131050.614991:6768087841:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x60200000e6b0\n[2902:2902:0120/131050.615011:6768087881:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x60200000e6d0 with delay 1000\n[2902:2902:0120/131050.615083:6768087934:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x60200000e6d0\n[2902:2902:0120/131050.615105:6768087955:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x60200000e6f0 with delay 1000\n[2902:2902:0120/131050.615150:6768088001:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x60200000e6f0\n[2902:2902:0120/131050.615217:6768088068:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x60200000e710 with delay 1000\n[2902:2902:0120/131050.615258:6768088108:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x60200000e710\n[2902:2902:0120/131050.615277:6768088127:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x60200000e730 with delay 1000\n[2902:2902:0120/131050.615313:6768088162:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x60200000e730\n[2902:2902:0120/131050.615344:6768088196:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x60200000e750 with delay 54000\n[2902:2902:0120/131050.616357:6768089216:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x60200000e750\n[2902:2902:0120/131050.616421:6768089272:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x60200000e770 with delay 1000\n[2902:2902:0120/131050.616488:6768089340:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x60200000e770\n[2902:2902:0120/131050.616510:6768089360:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x60200000e790 with delay 1000\n[2902:2902:0120/131050.616556:6768089407:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x60200000e790\n[2902:2902:0120/131050.616577:6768089427:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x60200000e7b0 with delay 1000\n[2902:2902:0120/131050.616608:6768089458:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x60200000e7b0\n[2902:2902:0120/131050.616627:6768089477:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x60200000e7d0 with delay 1000\n[2902:2902:0120/131050.616659:6768089510:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x60200000e7d0\n[2902:2902:0120/131050.616678:6768089528:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x60200000e7f0 with delay 1000\n[2902:2902:0120/131050.616713:6768089563:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x60200000e7f0\n[2902:2902:0120/131050.616732:6768089581:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x60200000e810 with delay 1000\n[2902:2902:0120/131050.616760:6768089610:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x60200000e810\n[2902:2902:0120/131050.616784:6768089636:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x60200000e830 with delay 54000\n[2902:2902:0120/131050.617371:6768090223:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x60200000e830\n[2902:2902:0120/131050.617408:6768090261:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x60200000e850 with delay 1000\n[2902:2902:0120/131050.617464:6768090314:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x60200000e850\n[2902:2902:0120/131050.617485:6768090335:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x60200000e870 with delay 1000\n[2902:2902:0120/131050.617519:6768090368:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x60200000e870\n[2902:2902:0120/131050.617537:6768090387:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x60200000e890 with delay 1000\n[2902:2902:0120/131050.617575:6768090428:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x60200000e890\n[2902:2902:0120/131050.617598:6768090448:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x60200000e8b0 with delay 1000\n[2902:2902:0120/131050.617626:6768090476:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x60200000e8b0\n[2902:2902:0120/131050.617644:6768090493:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x60200000e8d0 with delay 1000\n[2902:2902:0120/131050.617671:6768090522:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x60200000e8d0\n[2902:2902:0120/131050.617691:6768090540:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x60200000e8f0 with delay 1000\n[2902:2902:0120/131050.617724:6768090574:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x60200000e8f0\n[2902:2902:0120/131050.617744:6768090593:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x60200000e910 with delay 54000\n[2902:2902:0120/131050.618402:6768091260:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x60200000e910\n[2902:2902:0120/131050.618466:6768091319:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x60200000e930 with delay 1000\n[2902:2902:0120/131050.618501:6768091350:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x60200000e930\n[2902:2902:0120/131050.618519:6768091369:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x60200000e950 with delay 1000\n[2902:2902:0120/131050.618547:6768091397:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x60200000e950\n[2902:2902:0120/131050.618566:6768091416:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x60200000e970 with delay 1000\n[2902:2902:0120/131050.618614:6768091465:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x60200000e970\n[2902:2902:0120/131050.618637:6768091486:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x60200000e990 with delay 1000\n[2902:2902:0120/131050.618688:6768091539:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x60200000e990\n[2902:2902:0120/131050.618710:6768091560:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x60200000e9b0 with delay 1000\n[2902:2902:0120/131050.618738:6768091587:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x60200000e9b0\n[2902:2902:0120/131050.618755:6768091605:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x60200000e9d0 with delay 1000\n[2902:2902:0120/131050.618781:6768091631:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x60200000e9d0\n[2902:2902:0120/131050.618809:6768091660:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x60200000e9f0 with delay 54000\n[2902:2902:0120/131050.619473:6768092326:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x60200000e9f0\n[2902:2902:0120/131050.619547:6768092398:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x60200000ea10 with delay 1000\n[2902:2902:0120/131050.619579:6768092429:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x60200000ea10\n[2902:2902:0120/131050.619605:6768092457:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x60200000ea30 with delay 1000\n[2902:2902:0120/131050.619635:6768092485:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x60200000ea30\n[2902:2902:0120/131050.619653:6768092502:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x60200000ea50 with delay 1000\n[2902:2902:0120/131050.619689:6768092540:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x60200000ea50\n[2902:2902:0120/131050.619712:6768092562:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x60200000ea70 with delay 1000\n[2902:2902:0120/131050.619742:6768092592:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x60200000ea70\n[2902:2902:0120/131050.619761:6768092610:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x60200000ea90 with delay 1000\n[2902:2902:0120/131050.619796:6768092647:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x60200000ea90\n[2902:2902:0120/131050.619816:6768092665:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x60200000eab0 with delay 1000\n[2902:2902:0120/131050.619842:6768092692:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x60200000eab0\n[2902:2902:0120/131050.619860:6768092709:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x60200000ead0 with delay 54000\n[2902:2902:0120/131050.620452:6768093304:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x60200000ead0\n[ OK ] ThrottleTest.ThrottlingStorm (6 ms)\n[8/28] ThrottleTest.ThrottlingStorm (6 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[2900:2900:0120/131050.585084:6768057948:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9d0 with delay 0\n[2900:2900:0120/131050.585411:6768058270:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.585708:6768058560:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000de70 with delay 0\n[2900:2900:0120/131050.585739:6768058591:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9d0\n[2900:2900:0120/131050.585774:6768058628:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000de70\n[2900:2900:0120/131050.585834:6768058684:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.585904:6768058759:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000df10 with delay 0\n[2900:2900:0120/131050.585948:6768058802:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000df10\n[2900:2900:0120/131050.585981:6768058832:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.586009:6768058859:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000df50 with delay 0\n[2900:2900:0120/131050.586050:6768058904:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000df50\n[2900:2900:0120/131050.586076:6768058926:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.586104:6768058955:INFO:recurring-task.cc(55)] [Startup] Scheduling 33320 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.586140:6768058994:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000df70 with delay 0\n[2900:2900:0120/131050.586174:6768059025:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000df70\n[2900:2900:0120/131050.586240:6768059092:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"7551769572042793155\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.586288:6768059140:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 33576 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.586321:6768059171:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000df90 with delay 500\n[2900:2900:0120/131050.586349:6768059199:INFO:recurring-task.cc(55)] [Retry] Scheduling 33320 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.586396:6768059252:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000dfb0 with delay 60000\n[2900:2900:0120/131050.586427:6768059296:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000df90\n[2900:2900:0120/131050.586472:6768059327:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.586545:6768059399:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.586681:6768059533: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: \"7551769572042793155\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.586846:6768059698:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000e030 with delay 0\n[2900:2900:0120/131050.586879:6768059734:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000e030\n[2900:2900:0120/131050.586976:6768059830:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"7551769572042793155\" 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[2900:2900:0120/131050.587042:6768059895:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"7551769572042793155\"\n[2900:2900:0120/131050.587080:6768059931:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.587116:6768059970:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 32984 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.587184:6768060037:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000e050 with delay 1200000\n[2900:2900:0120/131050.587222:6768060074:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.587378:6768060232:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.587420:6768060272:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 67080 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.587464:6768060315:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000e230 with delay 0\n[2900:2900:0120/131050.587519:6768060371: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[2900:2900:0120/131050.587567:6768060419:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000e230\n[2900:2900:0120/131050.587642:6768060495:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000e2d0 with delay 0\n[2900:2900:0120/131050.587692:6768060543:INFO:recurring-task.cc(55)] [Retry] Scheduling 67080 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.587720:6768060576:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000e310 with delay 10000\n[2900:2900:0120/131050.587759:6768060611:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000e2d0\n[2900:2900:0120/131050.587785:6768060634:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (4 ms)\n[9/28] InvalidationClientImplTest.Start (4 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[2900:2900:0120/131050.588460:6768061314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e9f0 with delay 0\n[2900:2900:0120/131050.588515:6768061368:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (0 ms)\n[10/28] InvalidationClientImplTest.GenerateNonce (0 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[2900:2900:0120/131050.588963:6768061817:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f110 with delay 0\n[2900:2900:0120/131050.589006:6768061858:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.589272:6768062125:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f6f0 with delay 0\n[2900:2900:0120/131050.589333:6768062186:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000f110\n[2900:2900:0120/131050.589374:6768062227:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000f6f0\n[2900:2900:0120/131050.589447:6768062301:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.589506:6768062358:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f790 with delay 0\n[2900:2900:0120/131050.589548:6768062401:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000f790\n[2900:2900:0120/131050.589575:6768062425:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.589606:6768062457:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f7d0 with delay 0\n[2900:2900:0120/131050.589645:6768062497:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000f7d0\n[2900:2900:0120/131050.589670:6768062520:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.589697:6768062548:INFO:recurring-task.cc(55)] [Startup] Scheduling 54440 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.589720:6768062574:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f7f0 with delay 0\n[2900:2900:0120/131050.589747:6768062597:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000f7f0\n[2900:2900:0120/131050.589805:6768062657:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2670988649513544427\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.589845:6768062697:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 54696 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.589876:6768062728:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f810 with delay 500\n[2900:2900:0120/131050.589906:6768062757:INFO:recurring-task.cc(55)] [Retry] Scheduling 54440 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.589941:6768062793:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f830 with delay 60000\n[2900:2900:0120/131050.589978:6768062828:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000f810\n[2900:2900:0120/131050.590004:6768062854:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.590046:6768062899:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.590187:6768063039: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: \"2670988649513544427\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.590299:6768063151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000f8b0 with delay 0\n[2900:2900:0120/131050.590335:6768063190:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000f8b0\n[2900:2900:0120/131050.590466:6768063318:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2670988649513544427\" 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[2900:2900:0120/131050.590526:6768063378:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2670988649513544427\"\n[2900:2900:0120/131050.590565:6768063417:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.590596:6768063448:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 35800 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.590639:6768063490:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000f8d0 with delay 1200000\n[2900:2900:0120/131050.590680:6768063532:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.590826:6768063684:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.590865:6768063716:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 71304 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.590897:6768063749:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000fab0 with delay 0\n[2900:2900:0120/131050.590942:6768063794: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[2900:2900:0120/131050.590987:6768063840:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000fab0\n[2900:2900:0120/131050.591055:6768063907:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000fb50 with delay 0\n[2900:2900:0120/131050.591090:6768063946:INFO:recurring-task.cc(55)] [Retry] Scheduling 71304 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.591121:6768063970:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000fb90 with delay 10000\n[2900:2900:0120/131050.591153:6768064107:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000fb50\n[2900:2900:0120/131050.591282:6768064133:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.591352:6768064204:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000fbb0 with delay 0\n[2900:2900:0120/131050.591381:6768064232:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000fbb0\n[2900:2900:0120/131050.591428:6768064293:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[2900:2900:0120/131050.591480:6768064330:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[2900:2900:0120/131050.591506:6768064355:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[2900:2900:0120/131050.591570:6768064421:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 54696 with a delay 500000, Now = 211469424\n[2900:2900:0120/131050.591599:6768064449:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000fbd0 with delay 500\n[2900:2900:0120/131050.591625:6768064485:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 54568 with a delay 60000000, Now = 211469424\n[2900:2900:0120/131050.591661:6768064512:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000fbf0 with delay 60000\n[2900:2900:0120/131050.591703:6768064555:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000fbd0\n[2900:2900:0120/131050.591733:6768064584:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.591783:6768064634:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.591816:6768064668:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2900:2900:0120/131050.591974:6768064826: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[2900:2900:0120/131050.592058:6768064911:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.592141:6768064992:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000fc70 with delay 0\n[2900:2900:0120/131050.592178:6768065029:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000fc70\n[2900:2900:0120/131050.592365:6768065215: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[2900:2900:0120/131050.592464:6768065315: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[2900:2900:0120/131050.592538:6768065391:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[2900:2900:0120/131050.592647:6768065498:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[2900:2900:0120/131050.592725:6768065576:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[2900:2900:0120/131050.592843:6768065693:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000fb90\n[ OK ] InvalidationClientImplTest.Register (5 ms)\n[11/28] InvalidationClientImplTest.Register (5 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[2900:2900:0120/131050.593621:6768066488:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010610 with delay 0\n[2900:2900:0120/131050.593688:6768066539:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.593939:6768066791:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010bf0 with delay 0\n[2900:2900:0120/131050.593973:6768066824:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000010610\n[2900:2900:0120/131050.593998:6768066850:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000010bf0\n[2900:2900:0120/131050.594046:6768066898:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.594113:6768066965:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010c90 with delay 0\n[2900:2900:0120/131050.594161:6768067012:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000010c90\n[2900:2900:0120/131050.594191:6768067041:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.594219:6768067069:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010cd0 with delay 0\n[2900:2900:0120/131050.594249:6768067101:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000010cd0\n[2900:2900:0120/131050.594272:6768067123:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.594306:6768067158:INFO:recurring-task.cc(55)] [Startup] Scheduling 81832 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.594330:6768067183:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010cf0 with delay 0\n[2900:2900:0120/131050.594355:6768067205:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000010cf0\n[2900:2900:0120/131050.594419:6768067271:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2486438440766728510\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.594471:6768067322:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 82088 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.594499:6768067352:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010d10 with delay 500\n[2900:2900:0120/131050.594539:6768067390:INFO:recurring-task.cc(55)] [Retry] Scheduling 81832 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.594566:6768067415:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010d30 with delay 60000\n[2900:2900:0120/131050.594590:6768067440:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000010d10\n[2900:2900:0120/131050.594617:6768067469:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.594668:6768067520:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.594789:6768067641: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: \"-2486438440766728510\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.594875:6768067729:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000010db0 with delay 0\n[2900:2900:0120/131050.594921:6768067776:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000010db0\n[2900:2900:0120/131050.595019:6768067872:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2486438440766728510\" 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[2900:2900:0120/131050.595085:6768067937:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2486438440766728510\"\n[2900:2900:0120/131050.595115:6768067965:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.595153:6768068026:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 41256 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.595209:6768068062:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000010dd0 with delay 1200000\n[2900:2900:0120/131050.595241:6768068093:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.595371:6768068222:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.595419:6768068272:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 78024 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.595465:6768068318:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000010fb0 with delay 0\n[2900:2900:0120/131050.595529:6768068380: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[2900:2900:0120/131050.595570:6768068423:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000010fb0\n[2900:2900:0120/131050.595649:6768068502:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011050 with delay 0\n[2900:2900:0120/131050.595684:6768068536:INFO:recurring-task.cc(55)] [Retry] Scheduling 78024 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.595728:6768068580:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011090 with delay 10000\n[2900:2900:0120/131050.595762:6768068614:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011050\n[2900:2900:0120/131050.595786:6768068636:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.595831:6768068683:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.595885:6768068737:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000110b0 with delay 0\n[2900:2900:0120/131050.595909:6768068759:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000110b0\n[2900:2900:0120/131050.596077:6768068929: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[2900:2900:0120/131050.596168:6768069029: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[2900:2900:0120/131050.596280:6768069133: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[2900:2900:0120/131050.596392:6768069243: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[2900:2900:0120/131050.596475:6768069326: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[2900:2900:0120/131050.596540:6768069391:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000011370 with delay 0\n[2900:2900:0120/131050.596576:6768069428:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000011390 with delay 0\n[2900:2900:0120/131050.596602:6768069453:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x6020000113b0 with delay 0\n[2900:2900:0120/131050.596626:6768069488:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000011370\n[2900:2900:0120/131050.596680:6768069533:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 82088 with a delay 500000, Now = 211519424\n[2900:2900:0120/131050.596706:6768069556:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x6020000113d0 with delay 500\n[2900:2900:0120/131050.596733:6768069584:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000011390\n[2900:2900:0120/131050.596763:6768069615:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x6020000113b0\n[2900:2900:0120/131050.596793:6768069644:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x6020000113d0\n[2900:2900:0120/131050.596836:6768069687:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.596878:6768069730:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.596913:6768069764:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2900:2900:0120/131050.597097:6768069949: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 (4 ms)\n[12/28] InvalidationClientImplTest.Invalidations (4 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[2900:2900:0120/131050.597751:6768070605:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011b10 with delay 0\n[2900:2900:0120/131050.597797:6768070650:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.598001:6768070853:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011fb0 with delay 0\n[2900:2900:0120/131050.598033:6768070884:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011b10\n[2900:2900:0120/131050.598057:6768070907:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011fb0\n[2900:2900:0120/131050.598110:6768070960:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.598165:6768071017:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012050 with delay 0\n[2900:2900:0120/131050.598198:6768071049:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012050\n[2900:2900:0120/131050.598220:6768071072:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.598247:6768071097:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012090 with delay 0\n[2900:2900:0120/131050.598269:6768071120:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012090\n[2900:2900:0120/131050.598292:6768071142:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.598318:6768071168:INFO:recurring-task.cc(55)] [Startup] Scheduling 107560 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.598343:6768071192:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000120b0 with delay 0\n[2900:2900:0120/131050.598364:6768071215:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000120b0\n[2900:2900:0120/131050.598423:6768071291:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2023416849516140083\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.598475:6768071327:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 107816 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.598508:6768071360:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000120d0 with delay 500\n[2900:2900:0120/131050.598534:6768071384:INFO:recurring-task.cc(55)] [Retry] Scheduling 107560 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.598558:6768071408:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000120f0 with delay 60000\n[2900:2900:0120/131050.598592:6768071444:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000120d0\n[2900:2900:0120/131050.598619:6768071470:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.598668:6768071520:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.598790:6768071641: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: \"2023416849516140083\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.598881:6768071732:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012170 with delay 0\n[2900:2900:0120/131050.598917:6768071770:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012170\n[2900:2900:0120/131050.599025:6768071877:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2023416849516140083\" 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[2900:2900:0120/131050.599069:6768071922:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2023416849516140083\"\n[2900:2900:0120/131050.599102:6768071953:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.599139:6768071990:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 66248 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.599203:6768072055:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012190 with delay 1200000\n[2900:2900:0120/131050.599242:6768072093:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.599360:6768072214:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.599395:6768072247:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 84168 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.599422:6768072274:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012370 with delay 0\n[2900:2900:0120/131050.599485:6768072337: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[2900:2900:0120/131050.599522:6768072374:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012370\n[2900:2900:0120/131050.599585:6768072436:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012410 with delay 0\n[2900:2900:0120/131050.599619:6768072609:INFO:recurring-task.cc(55)] [Retry] Scheduling 84168 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.599797:6768072649:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012450 with delay 10000\n[2900:2900:0120/131050.599822:6768072675:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012410\n[2900:2900:0120/131050.599847:6768072697:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.599887:6768072738:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.599939:6768072791:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000012470 with delay 0\n[2900:2900:0120/131050.599969:6768072820:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000012470\n[2900:2900:0120/131050.600080:6768072932: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[2900:2900:0120/131050.600152:6768073003: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[2900:2900:0120/131050.600194:6768073046:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[2900:2900:0120/131050.600222:6768073073:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 107816 with a delay 500000, Now = 211469424\n[2900:2900:0120/131050.600254:6768073105:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000012490 with delay 500\n[2900:2900:0120/131050.600290:6768073141:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[2900:2900:0120/131050.600471:6768073324: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[2900:2900:0120/131050.600525:6768073378:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000012490\n[2900:2900:0120/131050.600554:6768073405:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.600638:6768073490:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.600674:6768073527:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2900:2900:0120/131050.600938:6768073789: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[2900:2900:0120/131050.601073:6768073923:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000012450\n[ OK ] InvalidationClientImplTest.ServerRequests (4 ms)\n[13/28] InvalidationClientImplTest.ServerRequests (4 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[2900:2900:0120/131050.601834:6768074687:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012bd0 with delay 0\n[2900:2900:0120/131050.601883:6768074736:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.602088:6768074940:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000013130 with delay 0\n[2900:2900:0120/131050.602124:6768074976:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012bd0\n[2900:2900:0120/131050.602160:6768075011:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000013130\n[2900:2900:0120/131050.602210:6768075063:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.602261:6768075112:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000131d0 with delay 0\n[2900:2900:0120/131050.602295:6768075147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000131d0\n[2900:2900:0120/131050.602317:6768075168:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.602342:6768075192:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000013210 with delay 0\n[2900:2900:0120/131050.602364:6768075216:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000013210\n[2900:2900:0120/131050.602386:6768075244:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.602422:6768075274:INFO:recurring-task.cc(55)] [Startup] Scheduling 131624 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.602470:6768075322:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000013230 with delay 0\n[2900:2900:0120/131050.602495:6768075345:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000013230\n[2900:2900:0120/131050.602547:6768075399:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1615294574052135881\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.602582:6768075433:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 131880 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.602612:6768075463:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000013250 with delay 500\n[2900:2900:0120/131050.602652:6768075504:INFO:recurring-task.cc(55)] [Retry] Scheduling 131624 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.602679:6768075529:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000013270 with delay 60000\n[2900:2900:0120/131050.602705:6768075555:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000013250\n[2900:2900:0120/131050.602727:6768075577:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.602762:6768075613:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.602869:6768075721: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: \"-1615294574052135881\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.602960:6768075812:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000132f0 with delay 0\n[2900:2900:0120/131050.602993:6768075844:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000132f0\n[2900:2900:0120/131050.603115:6768075967:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1615294574052135881\" 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[2900:2900:0120/131050.603191:6768076042:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1615294574052135881\"\n[2900:2900:0120/131050.603229:6768076081:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.603261:6768076112:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 69944 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.603286:6768076136:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000013310 with delay 1200000\n[2900:2900:0120/131050.603313:6768076164:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.603428:6768076293:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.603475:6768076327:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 89544 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.603504:6768076355:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000134f0 with delay 0\n[2900:2900:0120/131050.603546:6768076399: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[2900:2900:0120/131050.603581:6768076432:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000134f0\n[2900:2900:0120/131050.603645:6768076496:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000013590 with delay 0\n[2900:2900:0120/131050.603678:6768076530:INFO:recurring-task.cc(55)] [Retry] Scheduling 89544 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.603704:6768076556:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000135d0 with delay 10000\n[2900:2900:0120/131050.603729:6768076578:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000013590\n[2900:2900:0120/131050.603758:6768076613:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.603806:6768076658:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.603847:6768076699:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000135f0 with delay 0\n[2900:2900:0120/131050.603873:6768076725:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000135f0\n[2900:2900:0120/131050.603977:6768076829: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[2900:2900:0120/131050.604038:6768076890: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[2900:2900:0120/131050.604066:6768076918:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[2900:2900:0120/131050.604185:6768077035:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000135d0\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (3 ms)\n[14/28] InvalidationClientImplTest.IncomingErrorMessage (3 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[2900:2900:0120/131050.604926:6768077779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000013db0 with delay 0\n[2900:2900:0120/131050.604972:6768077825:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.605244:6768078096:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000014410 with delay 0\n[2900:2900:0120/131050.605276:6768078128:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000013db0\n[2900:2900:0120/131050.605302:6768078152:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000014410\n[2900:2900:0120/131050.605353:6768078204:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.605405:6768078257:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000144b0 with delay 0\n[2900:2900:0120/131050.605462:6768078313:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000144b0\n[2900:2900:0120/131050.605485:6768078335:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.605507:6768078357:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000144f0 with delay 0\n[2900:2900:0120/131050.605538:6768078390:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000144f0\n[2900:2900:0120/131050.605560:6768078411:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.605593:6768078444:INFO:recurring-task.cc(55)] [Startup] Scheduling 151208 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.605621:6768078484:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000014510 with delay 0\n[2900:2900:0120/131050.605663:6768078514:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000014510\n[2900:2900:0120/131050.605713:6768078564:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7195434024683792476\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.605745:6768078598:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 151464 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.605771:6768078621:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000014530 with delay 500\n[2900:2900:0120/131050.605803:6768078654:INFO:recurring-task.cc(55)] [Retry] Scheduling 151208 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.605828:6768078680:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000014550 with delay 60000\n[2900:2900:0120/131050.605881:6768078733:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000014530\n[2900:2900:0120/131050.605910:6768078759:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.605945:6768078796:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.606056:6768078907: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: \"-7195434024683792476\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.606149:6768079001:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000145d0 with delay 0\n[2900:2900:0120/131050.606178:6768079028:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000145d0\n[2900:2900:0120/131050.606272:6768079123:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7195434024683792476\" 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[2900:2900:0120/131050.606324:6768079177:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7195434024683792476\"\n[2900:2900:0120/131050.606353:6768079207:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.606394:6768079245:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 73464 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.606421:6768079271:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000145f0 with delay 1200000\n[2900:2900:0120/131050.606469:6768079320:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.606577:6768079429:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.606613:6768079465:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 93000 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.606665:6768079517:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000147d0 with delay 0\n[2900:2900:0120/131050.606709:6768079560: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[2900:2900:0120/131050.606743:6768079595:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000147d0\n[2900:2900:0120/131050.606809:6768079662:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000014870 with delay 0\n[2900:2900:0120/131050.606844:6768079695:INFO:recurring-task.cc(55)] [Retry] Scheduling 93000 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.606871:6768079721:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000148b0 with delay 10000\n[2900:2900:0120/131050.606897:6768079748:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000014870\n[2900:2900:0120/131050.606920:6768079770:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.606959:6768079811:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000148d0 with delay 0\n[2900:2900:0120/131050.606993:6768079845:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000148d0\n[2900:2900:0120/131050.607029:6768079882:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[2900:2900:0120/131050.607078:6768079930:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 151464 with a delay 500000, Now = 211469424\n[2900:2900:0120/131050.607107:6768079958:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000148f0 with delay 500\n[2900:2900:0120/131050.607139:6768079997:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 151336 with a delay 60000000, Now = 211469424\n[2900:2900:0120/131050.607203:6768080054:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000014910 with delay 60000\n[2900:2900:0120/131050.607238:6768080090:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x6020000148f0\n[2900:2900:0120/131050.607270:6768080121:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.607310:6768080164:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.607336:6768080187:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2900:2900:0120/131050.607468:6768080321: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[2900:2900:0120/131050.607563:6768080417:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.607609:6768080461:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000014990 with delay 0\n[2900:2900:0120/131050.607740:6768080597:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000014990\n[2900:2900:0120/131050.607885:6768080736: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[2900:2900:0120/131050.607955:6768080807: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[2900:2900:0120/131050.607999:6768080850:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[2900:2900:0120/131050.608084:6768080936:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[2900:2900:0120/131050.608205:6768081056:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000148b0\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (4 ms)\n[15/28] InvalidationClientImplTest.IncomingAuthErrorMessage (4 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[2900:2900:0120/131050.608963:6768081817:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000015230 with delay 0\n[2900:2900:0120/131050.609014:6768081866:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.609232:6768082085:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000156d0 with delay 0\n[2900:2900:0120/131050.609270:6768082122:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000015230\n[2900:2900:0120/131050.609297:6768082148:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000156d0\n[2900:2900:0120/131050.609353:6768082206:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.609401:6768082253:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000015770 with delay 0\n[2900:2900:0120/131050.609461:6768082313:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000015770\n[2900:2900:0120/131050.609484:6768082336:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.609512:6768082362:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000157b0 with delay 0\n[2900:2900:0120/131050.609660:6768082512:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000157b0\n[2900:2900:0120/131050.609686:6768082536:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.609723:6768082574:INFO:recurring-task.cc(55)] [Startup] Scheduling 175912 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.609751:6768082603:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000157d0 with delay 0\n[2900:2900:0120/131050.609776:6768082626:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000157d0\n[2900:2900:0120/131050.609829:6768082680:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6796272187887540689\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.609867:6768082718:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 176168 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.609894:6768082746:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000157f0 with delay 500\n[2900:2900:0120/131050.609919:6768082769:INFO:recurring-task.cc(55)] [Retry] Scheduling 175912 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.609943:6768082794:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000015810 with delay 60000\n[2900:2900:0120/131050.609976:6768082828:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000157f0\n[2900:2900:0120/131050.610011:6768082863:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.610062:6768082913:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.610191:6768083043: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: \"6796272187887540689\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.610289:6768083141:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000015890 with delay 0\n[2900:2900:0120/131050.610318:6768083169:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000015890\n[2900:2900:0120/131050.610427:6768083295:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6796272187887540689\" 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[2900:2900:0120/131050.610490:6768083341:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6796272187887540689\"\n[2900:2900:0120/131050.610520:6768083373:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.610562:6768083414:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 77160 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.610589:6768083442:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000158b0 with delay 1200000\n[2900:2900:0120/131050.610624:6768083475:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.610730:6768083582:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.610762:6768083613:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 98376 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.610794:6768083645:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000015a90 with delay 0\n[2900:2900:0120/131050.610847:6768083700: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[2900:2900:0120/131050.610889:6768083741:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000015a90\n[2900:2900:0120/131050.610943:6768083794:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000015b30 with delay 0\n[2900:2900:0120/131050.610976:6768083828:INFO:recurring-task.cc(55)] [Retry] Scheduling 98376 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.611003:6768083854:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000015b70 with delay 10000\n[2900:2900:0120/131050.611032:6768083882:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000015b30\n[2900:2900:0120/131050.611057:6768083909:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.611109:6768083961:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000015b90 with delay 0\n[2900:2900:0120/131050.611141:6768083992:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000015b90\n[2900:2900:0120/131050.611207:6768084058:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[2900:2900:0120/131050.611261:6768084113:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 176168 with a delay 500000, Now = 211469424\n[2900:2900:0120/131050.611290:6768084142:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000015bb0 with delay 500\n[2900:2900:0120/131050.611321:6768084171:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 176040 with a delay 60000000, Now = 211469424\n[2900:2900:0120/131050.611344:6768084195:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000015bd0 with delay 60000\n[2900:2900:0120/131050.611375:6768084226:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000015bb0\n[2900:2900:0120/131050.611403:6768084253:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.611460:6768084312:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.611491:6768084343:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2900:2900:0120/131050.611631:6768084483: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[2900:2900:0120/131050.611738:6768084589:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000015b70\n[2900:2900:0120/131050.611938:6768084789:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x602000015810\n[2900:2900:0120/131050.611967:6768084819:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x602000015bd0\n[2900:2900:0120/131050.612026:6768084878: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[2900:2900:0120/131050.612058:6768084909:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[2900:2900:0120/131050.612123:6768084976: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[2900:2900:0120/131050.612165:6768085016:INFO:recurring-task.cc(55)] [Send-info] Scheduling 176168 with a delay 500000, Now = 271469424\n[2900:2900:0120/131050.612193:6768085044:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000015c50 with delay 500\n[2900:2900:0120/131050.612221:6768085073:INFO:recurring-task.cc(55)] [Retry] Scheduling 176040 with a delay 60000000, Now = 271469424\n[2900:2900:0120/131050.612246:6768085098:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000015c70 with delay 60000\n[2900:2900:0120/131050.612276:6768085126:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x602000015c50\n[2900:2900:0120/131050.612299:6768085151:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.612346:6768085197:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.612370:6768085224:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2900:2900:0120/131050.612528:6768085380: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 (4 ms)\n[16/28] InvalidationClientImplTest.NetworkTimeouts (4 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[2900:2900:0120/131050.613273:6768086126:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000163b0 with delay 0\n[2900:2900:0120/131050.613319:6768086172:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.613569:6768086421:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000016850 with delay 0\n[2900:2900:0120/131050.613603:6768086455:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000163b0\n[2900:2900:0120/131050.613633:6768086485:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000016850\n[2900:2900:0120/131050.613689:6768086540:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.613734:6768086586:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000168f0 with delay 0\n[2900:2900:0120/131050.613765:6768086616:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000168f0\n[2900:2900:0120/131050.613788:6768086638:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.613822:6768086671:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000016930 with delay 0\n[2900:2900:0120/131050.613847:6768086697:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000016930\n[2900:2900:0120/131050.613867:6768086717:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.613894:6768086753:INFO:recurring-task.cc(55)] [Startup] Scheduling 200616 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.613933:6768086785:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000016950 with delay 0\n[2900:2900:0120/131050.613965:6768086815:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000016950\n[2900:2900:0120/131050.614017:6768086869:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6726376571259399981\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.614052:6768086903:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 200872 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.614081:6768086933:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000016970 with delay 500\n[2900:2900:0120/131050.614106:6768086956:INFO:recurring-task.cc(55)] [Retry] Scheduling 200616 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.614131:6768086981:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000016990 with delay 60000\n[2900:2900:0120/131050.614157:6768087008:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000016970\n[2900:2900:0120/131050.614179:6768087029:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.614217:6768087068:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.614330:6768087181: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: \"-6726376571259399981\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.614424:6768087296:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000016a10 with delay 0\n[2900:2900:0120/131050.614483:6768087335:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000016a10\n[2900:2900:0120/131050.614604:6768087456:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6726376571259399981\" 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[2900:2900:0120/131050.614653:6768087504:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6726376571259399981\"\n[2900:2900:0120/131050.614680:6768087532:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.614715:6768087565:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 80152 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.614740:6768087593:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000016a30 with delay 1200000\n[2900:2900:0120/131050.614767:6768087618:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.614881:6768087732:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.614916:6768087767:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 104520 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.614941:6768087791:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000016c10 with delay 0\n[2900:2900:0120/131050.614985:6768087835: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[2900:2900:0120/131050.615030:6768087882:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000016c10\n[2900:2900:0120/131050.615088:6768087940:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000016cb0 with delay 0\n[2900:2900:0120/131050.615121:6768087972:INFO:recurring-task.cc(55)] [Retry] Scheduling 104520 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.615150:6768088001:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000016cf0 with delay 10000\n[2900:2900:0120/131050.615201:6768088053:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000016cb0\n[2900:2900:0120/131050.615224:6768088075:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.615266:6768088116:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.615300:6768088151:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000016d10 with delay 0\n[2900:2900:0120/131050.615323:6768088174:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000016d10\n[2900:2900:0120/131050.615390:6768088240: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[2900:2900:0120/131050.615491:6768088343:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000016cf0\n[2900:2900:0120/131050.615725:6768088577: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 (2 ms)\n[17/28] InvalidationClientImplTest.NoRegistrationSummary (2 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[2900:2900:0120/131050.616254:6768089107:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000173f0 with delay 0\n[2900:2900:0120/131050.616297:6768089148:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2900:2900:0120/131050.616496:6768089348:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000017890 with delay 0\n[2900:2900:0120/131050.616555:6768089406:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000173f0\n[2900:2900:0120/131050.616585:6768089440:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000017890\n[2900:2900:0120/131050.616635:6768089487:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2900:2900:0120/131050.616690:6768089541:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000017930 with delay 0\n[2900:2900:0120/131050.616731:6768089582:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000017930\n[2900:2900:0120/131050.616753:6768089603:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2900:2900:0120/131050.616778:6768089628:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000017970 with delay 0\n[2900:2900:0120/131050.616802:6768089652:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000017970\n[2900:2900:0120/131050.616822:6768089672:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2900:2900:0120/131050.616848:6768089699:INFO:recurring-task.cc(55)] [Startup] Scheduling 219176 with a delay 0, Now = 210919424\n[2900:2900:0120/131050.616882:6768089733:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000017990 with delay 0\n[2900:2900:0120/131050.616907:6768089757:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000017990\n[2900:2900:0120/131050.616955:6768089806:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4684174491438357058\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2900:2900:0120/131050.616985:6768089836:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 219432 with a delay 500000, Now = 210919424\n[2900:2900:0120/131050.617020:6768089871:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000179b0 with delay 500\n[2900:2900:0120/131050.617048:6768089899:INFO:recurring-task.cc(55)] [Retry] Scheduling 219176 with a delay 60000000, Now = 210919424\n[2900:2900:0120/131050.617073:6768089922:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000179d0 with delay 60000\n[2900:2900:0120/131050.617099:6768089949:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000179b0\n[2900:2900:0120/131050.617121:6768089973:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.617167:6768090020:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2900:2900:0120/131050.617273:6768090123: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: \"4684174491438357058\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2900:2900:0120/131050.617365:6768090216:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000017a50 with delay 0\n[2900:2900:0120/131050.617393:6768090243:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000017a50\n[2900:2900:0120/131050.617519:6768090371:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4684174491438357058\" 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[2900:2900:0120/131050.617578:6768090430:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4684174491438357058\"\n[2900:2900:0120/131050.617607:6768090459:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2900:2900:0120/131050.617640:6768090490:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 82968 with a delay 1200000000, Now = 211419424\n[2900:2900:0120/131050.617665:6768090519:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000017a70 with delay 1200000\n[2900:2900:0120/131050.617701:6768090552:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2900:2900:0120/131050.617820:6768090671:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.617853:6768090705:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 107976 with a delay 0, Now = 211419424\n[2900:2900:0120/131050.617878:6768090728:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000017c50 with delay 0\n[2900:2900:0120/131050.617918:6768090769: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[2900:2900:0120/131050.617951:6768090802:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000017c50\n[2900:2900:0120/131050.618004:6768090855:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000017cf0 with delay 0\n[2900:2900:0120/131050.618035:6768090888:INFO:recurring-task.cc(55)] [Retry] Scheduling 107976 with a delay 10000000, Now = 211419424\n[2900:2900:0120/131050.618067:6768090918:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000017d30 with delay 10000\n[2900:2900:0120/131050.618098:6768090949:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000017cf0\n[2900:2900:0120/131050.618119:6768090971:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2900:2900:0120/131050.618190:6768091040:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000017d30\n[2900:2900:0120/131050.618394:6768091246:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x6020000179d0\n[2900:2900:0120/131050.621574:6768094428:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x602000017a70\n[2900:2900:0120/131050.621639:6768094490:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.621692:6768094544:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2900:2900:0120/131050.621720:6768094572:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[2900:2900:0120/131050.621878:6768094728: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[2900:2900:0120/131050.621918:6768094769:INFO:recurring-task.cc(55)] [Send-info] Scheduling 219432 with a delay 500000, Now = 1411419424\n[2900:2900:0120/131050.621951:6768094802:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000017d50 with delay 500\n[2900:2900:0120/131050.621980:6768094830:INFO:recurring-task.cc(55)] [Retry] Scheduling 82968 with a delay 1200000000, Now = 1411419424\n[2900:2900:0120/131050.622012:6768094864:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000017d70 with delay 1200000\n[2900:2900:0120/131050.622042:6768094894:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x602000017d50\n[2900:2900:0120/131050.622067:6768094918:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.622126:6768094978:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2900:2900:0120/131050.622153:6768095003:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2900:2900:0120/131050.622350:6768095202: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 (7 ms)\n[18/28] InvalidationClientImplTest.Heartbeats (7 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[2903:2903:0120/131050.630574:6768103429:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d790 with delay 0\n[2903:2903:0120/131050.630789:6768103641:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d790\n[2903:2903:0120/131050.631062:6768103914: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[2903:2903:0120/131050.631119:6768103971:INFO:recurring-task.cc(55)] [Startup] Scheduling 33064 with a delay 500000, Now = 210919424\n[2903:2903:0120/131050.631146:6768103997:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d8f0 with delay 500\n[2903:2903:0120/131050.631208:6768104059:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d8f0\n[2903:2903:0120/131050.631405:6768104259: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 (1 ms)\n[19/28] ProtocolHandlerTest.SendInitializeOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[2903:2903:0120/131050.632298:6768105151: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[20/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[2903:2903:0120/131050.632740:6768105593:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e3b0 with delay 0\n[2903:2903:0120/131050.632791:6768105641:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e3d0 with delay 0\n[2903:2903:0120/131050.632820:6768105670:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e3f0 with delay 0\n[2903:2903:0120/131050.632876:6768105727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e410 with delay 0\n[2903:2903:0120/131050.632911:6768105761:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e430 with delay 0\n[2903:2903:0120/131050.632941:6768105791:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e450 with delay 0\n[2903:2903:0120/131050.633205:6768106058:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e3b0\n[2903:2903:0120/131050.633293:6768106146: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[2903:2903:0120/131050.633335:6768106185:INFO:recurring-task.cc(55)] [Send-info] Scheduling 44072 with a delay 500000, Now = 210919424\n[2903:2903:0120/131050.633362:6768106212:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e5b0 with delay 500\n[2903:2903:0120/131050.633397:6768106247:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e3d0\n[2903:2903:0120/131050.633426:6768106290:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e3f0\n[2903:2903:0120/131050.633472:6768106323:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e410\n[2903:2903:0120/131050.633529:6768106380:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e430\n[2903:2903:0120/131050.633561:6768106412:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e450\n[2903:2903:0120/131050.633604:6768106456:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[2903:2903:0120/131050.633636:6768106487:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000e5b0\n[2903:2903:0120/131050.633774:6768106625:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[2903:2903:0120/131050.634079:6768106932: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 (2 ms)\n[21/28] ProtocolHandlerTest.SendMultipleMessageTypes (2 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[2903:2903:0120/131050.635530:6768108383: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[22/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[2903:2903:0120/131050.636102:6768108954: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[2903:2903:0120/131050.636168:6768109022: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[2903:2903:0120/131050.636257:6768109108: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[2903:2903:0120/131050.636335:6768109187: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[23/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[2903:2903:0120/131050.636846:6768109698: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[2903:2903:0120/131050.636939:6768109791: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[24/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[2903:2903:0120/131050.637343:6768110195: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[25/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[2903:2903:0120/131050.637762:6768110615: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[2903:2903:0120/131050.637830:6768110682:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fdf0 with delay 0\n[2903:2903:0120/131050.637855:6768110707:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fdf0\n[2903:2903:0120/131050.637932:6768110783: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[2903:2903:0120/131050.637973:6768110825:INFO:recurring-task.cc(55)] [Send-info] Scheduling 73128 with a delay 500000, Now = 210919424\n[2903:2903:0120/131050.638012:6768110863:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fe10 with delay 500\n[2903:2903:0120/131050.638041:6768110891:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000fe10\n[2903:2903:0120/131050.638064:6768110914:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (5 ms)\n[26/28] ProtocolHandlerTest.ConfigMessage (5 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[2903:2903:0120/131050.643217:6768116070: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[27/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[2903:2903:0120/131050.643696:6768116549: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[28/28] ProtocolHandlerTest.TokenMismatch (0 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "063b883cdb49763210cb95bd6a81ae5961bb110b", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "4285eb115b34b811", "server_versions": [ "4004-c99644c" ], "started_ts": "2019-01-20T21:10:44.682805", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:ToTLinuxASan", "buildnumber:4770", "cpu:x86-64", "data:b5c1d81c08e25e580652c9b6a8d3bb050dd21d66", "gpu:none", "master:chromium.clang", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "pool:Chrome", "priority:25", "project:chromium", "purpose:CI", "purpose:luci", "purpose:post-commit", "service_account:none", "slavename:gce-trusty-32-0258d129-us-west1-c-m020", "spec_name:chromium.ci:ToTLinuxASan", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:5746c1addf0a4c286f58c69ab0c42aedaac6b5ff", "user:None" ], "task_id": "4285eb115b34b810", "try_number": "1" } ] }