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-a-d3zg" ] }, { "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": [ "4143-92e279d" ] }, { "key": "zone", "value": [ "us", "us-west", "us-west1", "us-west1-a" ] } ], "bot_id": "gce-trusty-e833d7b0-us-west1-a-d3zg", "bot_version": "6ffb32b8073817e6bfe6d23a0d439a6e47b4710e3a2ecab107c6ae41f5a37e6a", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "nFftZl2kFquaI2EUmPGwzbc5sIbCocl9L55UeASqlLsC" }, "packages": [ { "package_name": "infra/python/cpython/linux-amd64", "path": ".swarming_module", "version": "46c0c897ca0f053799ee41fd148bb7a47232df47" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": ".swarming_module", "version": "2737ea8ed9b958f4d5aa9ffe106115a649ada241" }, { "package_name": "infra/tools/luci/vpython-native/linux-amd64", "path": ".swarming_module", "version": "OAXVAmcUSrvDygYUrCDzv20LRono9938YOHPu0zKowgC" }, { "package_name": "infra/tools/luci/vpython/linux-amd64", "path": ".swarming_module", "version": "ucaOciwAE9aweCUDOrmSvyiwrjmbywuB0NzAGUXIHjAC" } ] }, "completed_ts": "2019-03-05T20:27:22.218942", "costs_usd": [ 0.0012575573540547136 ], "created_ts": "2019-03-05T20:27:11.141587", "duration": 0.9737491607666016, "modified_ts": "2019-03-05T20:27:22.218942", "name": "cacheinvalidation_unittests (with patch)/Ubuntu-14.04/8919f9dfee/linux_chromium_msan_rel_ng/1394", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n MSAN_OPTIONS=symbolize=0\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/ioeP3dRZ/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[13311:13311:0305/122720.826309:1089264576:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0\n[13311:13311:0305/122720.826396:1089264657:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80\n[13311:13311:0305/122720.826790:1089265050: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[13311:13311:0305/122720.826852:1089265112:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424\n[13311:13311:0305/122720.826896:1089265155:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 500\n[13311:13311:0305/122720.826950:1089265215:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b90\n[13311:13311:0305/122720.827077:1089265337:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[13311:13311:0305/122720.827119:1089265379:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\n[1/28] ProtocolHandlerTest.TokenMissing (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[13311:13311:0305/122720.827644:1089265907:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 0\n[13311:13311:0305/122720.827703:1089265963:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b90\n[13311:13311:0305/122720.827756:1089266016:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424\n[13311:13311:0305/122720.827797:1089266057:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 500\n[13311:13311:0305/122720.827852:1089266112:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b80\n[13311:13311:0305/122720.827961:1089266221:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[13311:13311:0305/122720.828058:1089266321: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[13311:13311:0305/122720.828133:1089266392: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[13311:13311:0305/122720.828294:1089266555: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[13311:13311:0305/122720.828441:1089266701: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[13311:13311:0305/122720.828938:1089267204:INFO:protocol-handler.cc(139)] Incoming message: { }\n[13311:13311:0305/122720.829010:1089267276:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[13311:13311:0305/122720.829059:1089267321: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[13311:13311:0305/122720.829350:1089267610:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 679714712 with a delay 10000, Now = 0\n[13311:13311:0305/122720.829394:1089267654:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10\n[13311:13311:0305/122720.829444:1089267704:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0\n[13311:13311:0305/122720.829482:1089267750:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[13311:13311:0305/122720.829538:1089267798:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 10000\n[13311:13311:0305/122720.829587:1089267848:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000a00 with delay 60\n[13311:13311:0305/122720.829630:1089267889:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x701000000a00\n[13311:13311:0305/122720.829664:1089267923:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[13311:13311:0305/122720.829700:1089267958:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 70000\n[13311:13311:0305/122720.829733:1089267992:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000009f0 with delay 60\n[13311:13311:0305/122720.829802:1089268060:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000009f0\n[13311:13311:0305/122720.829835:1089268093:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[13311:13311:0305/122720.829868:1089268126:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 130000\n[13311:13311:0305/122720.829902:1089268160:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x701000000a00 with delay 60\n[13311:13311:0305/122720.829936:1089268195:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x701000000a00\n[13311:13311:0305/122720.829969:1089268228:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[13311:13311:0305/122720.830014:1089268273:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 190000\n[13311:13311:0305/122720.830047:1089268306:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000009f0 with delay 60\n[13311:13311:0305/122720.830083:1089268341:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000009f0\n[13311:13311:0305/122720.830115:1089268374:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[13311:13311:0305/122720.830148:1089268406:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 250000\n[13311:13311:0305/122720.830180:1089268443:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x701000000a00 with delay 60\n[13311:13311:0305/122720.830219:1089268478:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x701000000a00\n[13311:13311:0305/122720.830251:1089268510:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[13311:13311:0305/122720.830284:1089268542:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 310000\n[13311:13311:0305/122720.830317:1089268576:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000009f0 with delay 60\n[13311:13311:0305/122720.830352:1089268610:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000009f0\n[13311:13311:0305/122720.830384:1089268643:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[13311:13311:0305/122720.830423:1089268682:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 370000\n[13311:13311:0305/122720.830456:1089268715:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x701000000a00 with delay 60\n[13311:13311:0305/122720.830492:1089268751:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x701000000a00\n[13311:13311:0305/122720.830529:1089268789:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (2 ms)\n[4/28] RecurringTaskTest.PeriodicTask (2 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[13311:13311:0305/122720.831779:1089270045:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 679714528 with a delay 10000, Now = 0\n[13311:13311:0305/122720.831835:1089270095:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000a00 with delay 10\n[13311:13311:0305/122720.831879:1089270138:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000a00\n[13311:13311:0305/122720.831919:1089270183:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[13311:13311:0305/122720.831985:1089270254:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 50000, Now = 10000\n[13311:13311:0305/122720.832036:1089270295:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 50\n[13311:13311:0305/122720.832077:1089270336:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000009f0\n[13311:13311:0305/122720.832115:1089270375:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[13311:13311:0305/122720.832164:1089270424:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 149000, Now = 60000\n[13311:13311:0305/122720.832212:1089270472:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x701000000a00 with delay 149\n[13311:13311:0305/122720.832256:1089270516:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x701000000a00\n[13311:13311:0305/122720.832295:1089270554:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[13311:13311:0305/122720.832332:1089270594:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 248000, Now = 210000\n[13311:13311:0305/122720.832372:1089270634:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000009f0 with delay 248\n[13311:13311:0305/122720.832417:1089270676:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000009f0\n[13311:13311:0305/122720.832456:1089270715:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[13311:13311:0305/122720.832495:1089270755:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 446000, Now = 460000\n[13311:13311:0305/122720.832536:1089270796:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x701000000a00 with delay 446\n[13311:13311:0305/122720.832584:1089270851:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x701000000a00\n[13311:13311:0305/122720.832632:1089270892:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[13311:13311:0305/122720.832672:1089270932:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 842000, Now = 910000\n[13311:13311:0305/122720.832713:1089270973:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000009f0 with delay 842\n[13311:13311:0305/122720.832769:1089271027:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000009f0\n[13311:13311:0305/122720.832802:1089271060:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[13311:13311:0305/122720.832835:1089271093:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 1040000, Now = 1760000\n[13311:13311:0305/122720.832868:1089271126:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x701000000a00 with delay 1040\n[13311:13311:0305/122720.832925:1089271183:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x701000000a00\n[13311:13311:0305/122720.832957:1089271216:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[13311:13311:0305/122720.833005:1089271263:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 1040000, Now = 2800000\n[13311:13311:0305/122720.833038:1089271297:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000009f0 with delay 1040\n[13311:13311:0305/122720.833095:1089271353:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000009f0\n[13311:13311:0305/122720.833127:1089271388:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[5/28] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[13311:13311:0305/122720.834319:1089272579:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 679714568 with a delay 10000, Now = 0\n[13311:13311:0305/122720.834367:1089272626:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10\n[13311:13311:0305/122720.834409:1089272668:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0\n[13311:13311:0305/122720.834445:1089272705:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[13311:13311:0305/122720.834486:1089272746:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 679714568 with a delay 10000, Now = 10000\n[13311:13311:0305/122720.834530:1089272790:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 10\n[13311:13311:0305/122720.834570:1089272829:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000009f0\n[13311:13311:0305/122720.834606:1089272869: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[13311:13311:0305/122720.835877:1089274137:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000009f0 with delay 920\n[13311:13311:0305/122720.835942:1089274201:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.836303:1089274569:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000009f0 with delay 45000\n[13311:13311:0305/122720.837463:1089275727:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009f0\n[ OK ] ThrottleTest.ThrottlingScripted (2 ms)\n[7/28] ThrottleTest.ThrottlingScripted (2 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[13311:13311:0305/122720.837630:1089275890:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 990\n[13311:13311:0305/122720.837717:1089275977:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.837794:1089276053:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.837859:1089276117:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.837894:1089276152:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.837955:1089276212:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.837999:1089276257:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.838061:1089276319:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.838095:1089276352:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.838155:1089276413:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.838193:1089276452:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.838254:1089276512:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.838292:1089276552:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x701000000a00 with delay 54000\n[13311:13311:0305/122720.839905:1089278164:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000000a00\n[13311:13311:0305/122720.839949:1089278207:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.840020:1089278278:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x701000000a00\n[13311:13311:0305/122720.840055:1089278313:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.840115:1089278373:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x701000000a00\n[13311:13311:0305/122720.840149:1089278407:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.840215:1089278472:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x701000000a00\n[13311:13311:0305/122720.840249:1089278507:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.840309:1089278567:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x701000000a00\n[13311:13311:0305/122720.840343:1089278601:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.840403:1089278661:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x701000000a00\n[13311:13311:0305/122720.840437:1089278695:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.840503:1089278761:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x701000000a00\n[13311:13311:0305/122720.840537:1089278795:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000009f0 with delay 54000\n[13311:13311:0305/122720.842164:1089280422:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.842206:1089280464:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.842267:1089280525:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.842301:1089280559:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.842362:1089280619:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.842395:1089280653:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.842456:1089280713:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.842489:1089280747:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.842549:1089280807:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.842583:1089280841:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.842643:1089280901:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.842677:1089280937:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.842739:1089280997:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.842773:1089281031:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x701000000a00 with delay 54000\n[13311:13311:0305/122720.844406:1089282664:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x701000000a00\n[13311:13311:0305/122720.844445:1089282703:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.844505:1089282763:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x701000000a00\n[13311:13311:0305/122720.844539:1089282797:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.844605:1089282863:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x701000000a00\n[13311:13311:0305/122720.844639:1089282897:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.844701:1089282959:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x701000000a00\n[13311:13311:0305/122720.844735:1089282995:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.844798:1089283055:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x701000000a00\n[13311:13311:0305/122720.844831:1089283089:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.844891:1089283149:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x701000000a00\n[13311:13311:0305/122720.844925:1089283183:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x701000000a00 with delay 1000\n[13311:13311:0305/122720.844986:1089283253:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x701000000a00\n[13311:13311:0305/122720.845029:1089283288:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000009f0 with delay 54000\n[13311:13311:0305/122720.846640:1089284898:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.846683:1089284943:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.846746:1089285004:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.846780:1089285038:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.846841:1089285098:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.846874:1089285132:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.846935:1089285192:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.846968:1089285226:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.847039:1089285297:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.847073:1089285331:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.847133:1089285391:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.847167:1089285425:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000009f0 with delay 1000\n[13311:13311:0305/122720.847232:1089285492:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000009f0\n[13311:13311:0305/122720.847267:1089285526:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x701000000a00 with delay 54000\n[13311:13311:0305/122720.848886:1089287144:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x701000000a00\n[ OK ] ThrottleTest.ThrottlingStorm (11 ms)\n[8/28] ThrottleTest.ThrottlingStorm (11 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[13310:13310:0305/122720.800304:1089238567:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0\n[13310:13310:0305/122720.800660:1089238933:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80\n[13310:13310:0305/122720.801067:1089239327: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[13310:13310:0305/122720.801141:1089239415:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424\n[13310:13310:0305/122720.801199:1089239472:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 500\n[13310:13310:0305/122720.801273:1089239533:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10\n[13310:13310:0305/122720.801579:1089239839:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } initialize_message: { client_type: 2 nonce: \"unit-test-nonce\" application_client_id: { client_type: 2 client_name: \"unit-test-client-id\" } digest_serialization_type: BYTE_BASED } }\n[ OK ] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[9/28] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[13310:13310:0305/122720.802809:1089241076:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"fake nonce\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } token_control_message: { new_token: \"new token\" } }\n[ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[10/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[13310:13310:0305/122720.803320:1089241580:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[13310:13310:0305/122720.803408:1089241671:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b40 with delay 0\n[13310:13310:0305/122720.803456:1089241718:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0\n[13310:13310:0305/122720.803524:1089241783:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b00 with delay 0\n[13310:13310:0305/122720.803561:1089241819:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ab0 with delay 0\n[13310:13310:0305/122720.803617:1089241889:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[13310:13310:0305/122720.804013:1089242273:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[13310:13310:0305/122720.804161:1089242427: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[13310:13310:0305/122720.804234:1089242495:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424\n[13310:13310:0305/122720.804280:1089242539:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c60 with delay 500\n[13310:13310:0305/122720.804329:1089242588:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b40\n[13310:13310:0305/122720.804381:1089242639:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0\n[13310:13310:0305/122720.804420:1089242678:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b00\n[13310:13310:0305/122720.804458:1089242715:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ab0\n[13310:13310:0305/122720.804495:1089242752:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[13310:13310:0305/122720.804553:1089242812:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[13310:13310:0305/122720.804612:1089242871:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c60\n[13310:13310:0305/122720.804772:1089243037:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[13310:13310:0305/122720.806503:1089244771:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } registration_message: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } registration: { object_id: { source: 2 name: \"oid1\" } op_type: UNREGISTER } registration: { object_id: { source: 2 name: \"oid2\" } op_type: UNREGISTER } } registration_sync_message: { subtree: { registered_object: { source: 2 name: \"oid0\" } } } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"unit-test\" } performance_counter: { name: \"x\" value: 3 } performance_counter: { name: \"y\" value: 81 } server_registration_summary_requested: true } }\n[ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms)\n[11/28] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[13310:13310:0305/122720.808300:1089246568:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } invalidation_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[12/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[13310:13310:0305/122720.808982:1089247256: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[13310:13310:0305/122720.809083:1089247343: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[13310:13310:0305/122720.809195:1089247457: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[13310:13310:0305/122720.809297:1089247559:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[13/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[13310:13310:0305/122720.809832:1089248100: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[13310:13310:0305/122720.809967:1089248232:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[14/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[13310:13310:0305/122720.810493:1089248753:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.MinorVersionMismatch (0 ms)\n[15/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[13310:13310:0305/122720.811054:1089249314: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[13310:13310:0305/122720.811121:1089249389:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a40 with delay 0\n[13310:13310:0305/122720.811171:1089249430:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a40\n[13310:13310:0305/122720.811264:1089249529: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[13310:13310:0305/122720.811334:1089249594:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424\n[13310:13310:0305/122720.811381:1089249647:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a50 with delay 500\n[13310:13310:0305/122720.811449:1089249715:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[13310:13310:0305/122720.811503:1089249767:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (45 ms)\n[16/28] ProtocolHandlerTest.ConfigMessage (45 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[13310:13310:0305/122720.856060:1089294321:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.ErrorMessage (1 ms)\n[17/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[13310:13310:0305/122720.856627:1089294894:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.TokenMismatch (0 ms)\n[18/28] ProtocolHandlerTest.TokenMismatch (0 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[13307:13307:0305/122720.774677:1089212942:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c80 with delay 0\n[13307:13307:0305/122720.775053:1089213314:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.775360:1089213621:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[13307:13307:0305/122720.775407:1089213667:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c80\n[13307:13307:0305/122720.775446:1089213704:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[13307:13307:0305/122720.775531:1089213791:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.775618:1089213880:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0\n[13307:13307:0305/122720.775671:1089213929:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0\n[13307:13307:0305/122720.775706:1089213970:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.775749:1089214009:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[13307:13307:0305/122720.775789:1089214047:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[13307:13307:0305/122720.775836:1089214095:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.775884:1089214144:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.775924:1089214183:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0\n[13307:13307:0305/122720.775961:1089214219:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0\n[13307:13307:0305/122720.776062:1089214324:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4870639173317762515\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.776118:1089214377:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.776157:1089214416:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 500\n[13307:13307:0305/122720.776196:1089214455:INFO:recurring-task.cc(55)] [Retry] Scheduling 9224 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.776235:1089214494:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e10 with delay 60000\n[13307:13307:0305/122720.776284:1089214545:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[13307:13307:0305/122720.776331:1089214590:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.776400:1089214659:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.776597:1089214859: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: \"4870639173317762515\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.776791:1089215055:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e50 with delay 0\n[13307:13307:0305/122720.776839:1089215098:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[13307:13307:0305/122720.776986:1089215263:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4870639173317762515\" 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[13307:13307:0305/122720.777075:1089215334:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4870639173317762515\"\n[13307:13307:0305/122720.777124:1089215384:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.777169:1089215429:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.777207:1089215469:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e90 with delay 1200000\n[13307:13307:0305/122720.777251:1089215514:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.777425:1089215685:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.777468:1089215729:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.777507:1089215767:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ea0 with delay 0\n[13307:13307:0305/122720.777586:1089215849: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[13307:13307:0305/122720.777643:1089215902:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ea0\n[13307:13307:0305/122720.777728:1089215992:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 0\n[13307:13307:0305/122720.777808:1089216067:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.777853:1089216112:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c80 with delay 10000\n[13307:13307:0305/122720.777894:1089216152:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0\n[13307:13307:0305/122720.777929:1089216188:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (5 ms)\n[19/28] InvalidationClientImplTest.Start (5 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[13307:13307:0305/122720.778669:1089216930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[13307:13307:0305/122720.778736:1089216995:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (0 ms)\n[20/28] InvalidationClientImplTest.GenerateNonce (0 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[13307:13307:0305/122720.779255:1089217515:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0\n[13307:13307:0305/122720.779316:1089217575:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.779591:1089217854:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0\n[13307:13307:0305/122720.779645:1089217905:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80\n[13307:13307:0305/122720.779690:1089217948:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0\n[13307:13307:0305/122720.779760:1089218019:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.779821:1089218081:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[13307:13307:0305/122720.779869:1089218128:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[13307:13307:0305/122720.779904:1089218163:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.779948:1089218207:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0\n[13307:13307:0305/122720.779985:1089218256:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0\n[13307:13307:0305/122720.780033:1089218296:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.780079:1089218343:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.780124:1089218384:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[13307:13307:0305/122720.780164:1089218422:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[13307:13307:0305/122720.780236:1089218495:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2360396143280116873\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.780275:1089218539:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9224 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.780316:1089218575:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 500\n[13307:13307:0305/122720.780355:1089218614:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.780394:1089218653:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 60000\n[13307:13307:0305/122720.780447:1089218706:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0\n[13307:13307:0305/122720.780484:1089218746:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.780536:1089218794:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.780682:1089218942: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: \"2360396143280116873\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.780803:1089219062:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 0\n[13307:13307:0305/122720.780844:1089219104:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0\n[13307:13307:0305/122720.780970:1089219230:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2360396143280116873\" 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[13307:13307:0305/122720.781047:1089219309:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2360396143280116873\"\n[13307:13307:0305/122720.781089:1089219353:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.781136:1089219395:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.781176:1089219435:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f10 with delay 1200000\n[13307:13307:0305/122720.781218:1089219477:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.781346:1089219606:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.781392:1089219651:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.781430:1089219690:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[13307:13307:0305/122720.781488:1089219747: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[13307:13307:0305/122720.781534:1089219792:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[13307:13307:0305/122720.781614:1089219874:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0\n[13307:13307:0305/122720.781666:1089219928:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.781706:1089219966:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e80 with delay 10000\n[13307:13307:0305/122720.781745:1089220018:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40\n[13307:13307:0305/122720.781796:1089220055:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.781883:1089220142:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f40 with delay 0\n[13307:13307:0305/122720.781924:1089220183:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f40\n[13307:13307:0305/122720.781976:1089220236:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[13307:13307:0305/122720.782039:1089220297:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[13307:13307:0305/122720.782086:1089220348:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[13307:13307:0305/122720.782175:1089220439:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9224 with a delay 500000, Now = 211469424\n[13307:13307:0305/122720.782218:1089220477:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500\n[13307:13307:0305/122720.782259:1089220519:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424\n[13307:13307:0305/122720.782301:1089220560:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f30 with delay 60000\n[13307:13307:0305/122720.782358:1089220617:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[13307:13307:0305/122720.782398:1089220657:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.782450:1089220713:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.782490:1089220750:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[13307:13307:0305/122720.782670:1089220931: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[13307:13307:0305/122720.782775:1089221035:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.782866:1089221126:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f20 with delay 0\n[13307:13307:0305/122720.782909:1089221168:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[13307:13307:0305/122720.783165:1089221425: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[13307:13307:0305/122720.783268:1089221528: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[13307:13307:0305/122720.783362:1089221621:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[13307:13307:0305/122720.783483:1089221742:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[13307:13307:0305/122720.783571:1089221829:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[13307:13307:0305/122720.783872:1089222131:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e80\n[ OK ] InvalidationClientImplTest.Register (7 ms)\n[21/28] InvalidationClientImplTest.Register (7 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[13307:13307:0305/122720.785513:1089223774:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dc0 with delay 0\n[13307:13307:0305/122720.785577:1089223835:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.785964:1089224225:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0\n[13307:13307:0305/122720.786028:1089224288:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000dc0\n[13307:13307:0305/122720.786066:1089224324:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30\n[13307:13307:0305/122720.786146:1089224405:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.786208:1089224468:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0\n[13307:13307:0305/122720.786254:1089224513:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40\n[13307:13307:0305/122720.786289:1089224548:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.786330:1089224589:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0\n[13307:13307:0305/122720.786377:1089224636:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30\n[13307:13307:0305/122720.786412:1089224672:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.786455:1089224714:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.786494:1089224753:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0\n[13307:13307:0305/122720.786532:1089224790:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40\n[13307:13307:0305/122720.786604:1089224864:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2277094100654161269\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.786650:1089224909:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.786688:1089224948:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 500\n[13307:13307:0305/122720.786726:1089224986:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.786765:1089225024:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ba0 with delay 60000\n[13307:13307:0305/122720.786813:1089225072:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30\n[13307:13307:0305/122720.786853:1089225112:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.786900:1089225161:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.787053:1089225312: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: \"-2277094100654161269\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.787166:1089225427:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c30 with delay 0\n[13307:13307:0305/122720.787206:1089225465:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30\n[13307:13307:0305/122720.787331:1089225592:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2277094100654161269\" 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[13307:13307:0305/122720.787392:1089225652:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2277094100654161269\"\n[13307:13307:0305/122720.787434:1089225693:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.787475:1089225734:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.787513:1089225772:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000\n[13307:13307:0305/122720.787553:1089225814:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.787680:1089225940:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.787722:1089225981:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.787762:1089226023:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0\n[13307:13307:0305/122720.787820:1089226080: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[13307:13307:0305/122720.787868:1089226126:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40\n[13307:13307:0305/122720.787933:1089226192:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f70 with delay 0\n[13307:13307:0305/122720.787979:1089226250:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.788031:1089226297:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000dc0 with delay 10000\n[13307:13307:0305/122720.788083:1089226347:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f70\n[13307:13307:0305/122720.788125:1089226385:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.788182:1089226441:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.788247:1089226507:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 0\n[13307:13307:0305/122720.788285:1089226546:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f70\n[13307:13307:0305/122720.788506:1089226771: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[13307:13307:0305/122720.788611:1089226871: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[13307:13307:0305/122720.788695:1089226954: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[13307:13307:0305/122720.788828:1089227087: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[13307:13307:0305/122720.788923:1089227182: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[13307:13307:0305/122720.789024:1089227283:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f70 with delay 0\n[13307:13307:0305/122720.789062:1089227327:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f40 with delay 0\n[13307:13307:0305/122720.789115:1089227374:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f50 with delay 0\n[13307:13307:0305/122720.789153:1089227412:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f70\n[13307:13307:0305/122720.789210:1089227469:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424\n[13307:13307:0305/122720.789250:1089227509:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000c30 with delay 500\n[13307:13307:0305/122720.789298:1089227557:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f40\n[13307:13307:0305/122720.789341:1089227599:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f50\n[13307:13307:0305/122720.789392:1089227651:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000000c30\n[13307:13307:0305/122720.789433:1089227693:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.789490:1089227756:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.789534:1089227793:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[13307:13307:0305/122720.789726:1089227988:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: \"2\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } }\n[ OK ] InvalidationClientImplTest.Invalidations (5 ms)\n[22/28] InvalidationClientImplTest.Invalidations (5 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[13307:13307:0305/122720.790448:1089228708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000eb0 with delay 0\n[13307:13307:0305/122720.790512:1089228770:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.790732:1089228991:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[13307:13307:0305/122720.790779:1089229038:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000eb0\n[13307:13307:0305/122720.790821:1089229079:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[13307:13307:0305/122720.790889:1089229148:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.790948:1089229208:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[13307:13307:0305/122720.791006:1089229264:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[13307:13307:0305/122720.791041:1089229303:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.791115:1089229374:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[13307:13307:0305/122720.791156:1089229415:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[13307:13307:0305/122720.791190:1089229450:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.791234:1089229492:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.791275:1089229534:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[13307:13307:0305/122720.791312:1089229570:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[13307:13307:0305/122720.791382:1089229641:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7245746805187843547\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.791424:1089229684:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.791468:1089229727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500\n[13307:13307:0305/122720.791507:1089229766:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.791546:1089229812:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d40 with delay 60000\n[13307:13307:0305/122720.791615:1089229884:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[13307:13307:0305/122720.791665:1089229924:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.791715:1089229975:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.791846:1089230107: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: \"-7245746805187843547\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.791957:1089230218:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0\n[13307:13307:0305/122720.792019:1089230278:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[13307:13307:0305/122720.792157:1089230418:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7245746805187843547\" 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[13307:13307:0305/122720.792214:1089230474:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7245746805187843547\"\n[13307:13307:0305/122720.792254:1089230514:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.792296:1089230555:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.792335:1089230594:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 1200000\n[13307:13307:0305/122720.792376:1089230637:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.792498:1089230757:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.792539:1089230798:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.792575:1089230837:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[13307:13307:0305/122720.792636:1089230895: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[13307:13307:0305/122720.792684:1089230942:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[13307:13307:0305/122720.792751:1089231010:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 0\n[13307:13307:0305/122720.792800:1089231059:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.792839:1089231098:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000eb0 with delay 10000\n[13307:13307:0305/122720.792878:1089231136:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c20\n[13307:13307:0305/122720.792917:1089231176:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.792971:1089231230:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.793043:1089231303:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000c20 with delay 0\n[13307:13307:0305/122720.793081:1089231347:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000c20\n[13307:13307:0305/122720.793217:1089231479: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[13307:13307:0305/122720.793293:1089231555: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[13307:13307:0305/122720.793344:1089231603:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[13307:13307:0305/122720.793385:1089231644:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424\n[13307:13307:0305/122720.793424:1089231683:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500\n[13307:13307:0305/122720.793466:1089231725:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[13307:13307:0305/122720.793750:1089232030: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[13307:13307:0305/122720.793856:1089232119:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[13307:13307:0305/122720.793900:1089232159:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.793979:1089232251:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.794029:1089232290:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[13307:13307:0305/122720.795595:1089233855: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[13307:13307:0305/122720.795927:1089234186:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000eb0\n[ OK ] InvalidationClientImplTest.ServerRequests (7 ms)\n[23/28] InvalidationClientImplTest.ServerRequests (7 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[13307:13307:0305/122720.797495:1089235756:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[13307:13307:0305/122720.797561:1089235820:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.797819:1089236079:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[13307:13307:0305/122720.797867:1089236127:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[13307:13307:0305/122720.797912:1089236170:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[13307:13307:0305/122720.797984:1089236257:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.798057:1089236317:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0\n[13307:13307:0305/122720.798108:1089236367:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0\n[13307:13307:0305/122720.798143:1089236403:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.798183:1089236442:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[13307:13307:0305/122720.798222:1089236480:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[13307:13307:0305/122720.798256:1089236515:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.798299:1089236558:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.798336:1089236598:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0\n[13307:13307:0305/122720.798376:1089236634:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0\n[13307:13307:0305/122720.798444:1089236703:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"5076339386007162298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.798487:1089236746:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.798526:1089236785:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500\n[13307:13307:0305/122720.798562:1089236824:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.798602:1089236861:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 60000\n[13307:13307:0305/122720.798653:1089236912:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[13307:13307:0305/122720.798693:1089236952:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.798739:1089236999:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.798876:1089237135: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: \"5076339386007162298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.798986:1089237258:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0\n[13307:13307:0305/122720.799042:1089237302:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[13307:13307:0305/122720.799170:1089237429:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"5076339386007162298\" 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[13307:13307:0305/122720.799231:1089237491:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"5076339386007162298\"\n[13307:13307:0305/122720.799282:1089237542:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.799325:1089237586:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.799364:1089237624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 1200000\n[13307:13307:0305/122720.799407:1089237667:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.799534:1089237795:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.799578:1089237841:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.799620:1089237879:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ae0 with delay 0\n[13307:13307:0305/122720.799678:1089237940: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[13307:13307:0305/122720.799727:1089237986:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ae0\n[13307:13307:0305/122720.799793:1089238052:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000009e0 with delay 0\n[13307:13307:0305/122720.799841:1089238100:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.799882:1089238141:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 10000\n[13307:13307:0305/122720.799918:1089238176:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000009e0\n[13307:13307:0305/122720.799952:1089238213:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.800022:1089238291:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.800101:1089238361:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000009e0 with delay 0\n[13307:13307:0305/122720.800144:1089238404:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000009e0\n[13307:13307:0305/122720.800269:1089238529: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[13307:13307:0305/122720.800347:1089238607: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[13307:13307:0305/122720.800400:1089238663:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[13307:13307:0305/122720.800749:1089239009:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000b50\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[24/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[13307:13307:0305/122720.802476:1089240737:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d90 with delay 0\n[13307:13307:0305/122720.802542:1089240801:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.802873:1089241136:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[13307:13307:0305/122720.802922:1089241182:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d90\n[13307:13307:0305/122720.802964:1089241222:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70\n[13307:13307:0305/122720.803047:1089241309:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.803120:1089241379:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0\n[13307:13307:0305/122720.803168:1089241426:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50\n[13307:13307:0305/122720.803210:1089241470:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.803251:1089241513:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[13307:13307:0305/122720.803292:1089241550:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70\n[13307:13307:0305/122720.803327:1089241586:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.803372:1089241631:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.803418:1089241677:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0\n[13307:13307:0305/122720.803460:1089241718:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50\n[13307:13307:0305/122720.803529:1089241788:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8205423036013500622\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.803570:1089241830:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.803610:1089241869:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 500\n[13307:13307:0305/122720.803648:1089241907:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.803688:1089241947:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 60000\n[13307:13307:0305/122720.803740:1089241999:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70\n[13307:13307:0305/122720.803777:1089242038:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.803827:1089242085:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.803967:1089242227: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: \"8205423036013500622\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.804103:1089242363:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e70 with delay 0\n[13307:13307:0305/122720.804146:1089242405:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70\n[13307:13307:0305/122720.804274:1089242534:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8205423036013500622\" 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[13307:13307:0305/122720.804334:1089242596:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8205423036013500622\"\n[13307:13307:0305/122720.804377:1089242637:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.804423:1089242682:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.804473:1089242732:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 1200000\n[13307:13307:0305/122720.804517:1089242776:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.804642:1089242901:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.804684:1089242943:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.804722:1089242981:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f50 with delay 0\n[13307:13307:0305/122720.804779:1089243038: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[13307:13307:0305/122720.804826:1089243084:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f50\n[13307:13307:0305/122720.804892:1089243151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f60 with delay 0\n[13307:13307:0305/122720.804941:1089243200:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.804981:1089243255:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d90 with delay 10000\n[13307:13307:0305/122720.805036:1089243294:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f60\n[13307:13307:0305/122720.805069:1089243328:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.805131:1089243390:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f60 with delay 0\n[13307:13307:0305/122720.805169:1089243428:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f60\n[13307:13307:0305/122720.805225:1089243484:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[13307:13307:0305/122720.805289:1089243548:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424\n[13307:13307:0305/122720.805329:1089243588:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 500\n[13307:13307:0305/122720.805367:1089243628:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9224 with a delay 60000000, Now = 211469424\n[13307:13307:0305/122720.805405:1089243664:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 60000\n[13307:13307:0305/122720.805461:1089243721:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50\n[13307:13307:0305/122720.805506:1089243765:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.805554:1089243815:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.805596:1089243857:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[13307:13307:0305/122720.805776:1089244038: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[13307:13307:0305/122720.805881:1089244140:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.805938:1089244197:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f50 with delay 0\n[13307:13307:0305/122720.805979:1089244250:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50\n[13307:13307:0305/122720.806121:1089244381: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[13307:13307:0305/122720.806197:1089244457: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[13307:13307:0305/122720.806237:1089244496:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[13307:13307:0305/122720.806336:1089244595:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[13307:13307:0305/122720.806683:1089244942:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000d90\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[13307:13307:0305/122720.808244:1089246504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c20 with delay 0\n[13307:13307:0305/122720.808307:1089246565:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.808527:1089246787:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[13307:13307:0305/122720.808571:1089246830:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c20\n[13307:13307:0305/122720.808611:1089246869:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[13307:13307:0305/122720.808681:1089246941:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.808742:1089247002:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0\n[13307:13307:0305/122720.808786:1089247044:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20\n[13307:13307:0305/122720.808820:1089247081:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.808862:1089247121:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[13307:13307:0305/122720.808901:1089247159:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[13307:13307:0305/122720.808936:1089247197:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.809003:1089247263:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.809042:1089247304:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0\n[13307:13307:0305/122720.809082:1089247347:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20\n[13307:13307:0305/122720.809160:1089247419:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"248747909483240351\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.809203:1089247463:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.809245:1089247504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 500\n[13307:13307:0305/122720.809298:1089247557:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.809336:1089247598:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c50 with delay 60000\n[13307:13307:0305/122720.809388:1089247647:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[13307:13307:0305/122720.809432:1089247691:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.809488:1089247750:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.809631:1089247891: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: \"248747909483240351\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.809746:1089248042:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 0\n[13307:13307:0305/122720.809826:1089248085:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[13307:13307:0305/122720.809946:1089248205:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"248747909483240351\" 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[13307:13307:0305/122720.810016:1089248275:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"248747909483240351\"\n[13307:13307:0305/122720.810059:1089248318:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.810107:1089248366:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.810145:1089248410:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000\n[13307:13307:0305/122720.810191:1089248449:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.810316:1089248575:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.810355:1089248617:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.810395:1089248655:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 0\n[13307:13307:0305/122720.810456:1089248716: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[13307:13307:0305/122720.810510:1089248768:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e20\n[13307:13307:0305/122720.810578:1089248839:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0\n[13307:13307:0305/122720.810628:1089248887:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.810667:1089248926:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 10000\n[13307:13307:0305/122720.810704:1089248962:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[13307:13307:0305/122720.810738:1089249000:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.810796:1089249055:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0\n[13307:13307:0305/122720.810836:1089249095:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50\n[13307:13307:0305/122720.810892:1089249151:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[13307:13307:0305/122720.810955:1089249214:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424\n[13307:13307:0305/122720.811012:1089249272:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000e20 with delay 500\n[13307:13307:0305/122720.811055:1089249314:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424\n[13307:13307:0305/122720.811097:1089249356:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000af0 with delay 60000\n[13307:13307:0305/122720.811153:1089249412:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000e20\n[13307:13307:0305/122720.811193:1089249452:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.811241:1089249500:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.811279:1089249538:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[13307:13307:0305/122720.811417:1089249676: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[13307:13307:0305/122720.811713:1089249975:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c20\n[13307:13307:0305/122720.812877:1089251135:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000c50\n[13307:13307:0305/122720.812924:1089251182:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000af0\n[13307:13307:0305/122720.812986:1089251255: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[13307:13307:0305/122720.813037:1089251296:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[13307:13307:0305/122720.813128:1089251388: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[13307:13307:0305/122720.813177:1089251438:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424\n[13307:13307:0305/122720.813215:1089251475:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c50 with delay 500\n[13307:13307:0305/122720.813255:1089251514:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424\n[13307:13307:0305/122720.813294:1089251554:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c20 with delay 60000\n[13307:13307:0305/122720.813345:1089251604:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000c50\n[13307:13307:0305/122720.813382:1089251643:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.813435:1089251694:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.813474:1089251733:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[13307:13307:0305/122720.813625:1089251889:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 1 registration_digest: \"\\327\\003\\047\\242\\324@\\3740-O\\354\\3229\\352\\000\\231\\340\\204\\224\\323\" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: \"3\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } server_registration_summary_requested: true } }\n[ OK ] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[26/28] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[13307:13307:0305/122720.815448:1089253708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0\n[13307:13307:0305/122720.815512:1089253771:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.815722:1089253982:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[13307:13307:0305/122720.815765:1089254028:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30\n[13307:13307:0305/122720.815814:1089254074:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[13307:13307:0305/122720.815884:1089254143:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.815945:1089254205:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[13307:13307:0305/122720.816007:1089254267:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[13307:13307:0305/122720.816047:1089254308:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.816087:1089254353:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[13307:13307:0305/122720.816132:1089254390:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[13307:13307:0305/122720.816166:1089254426:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.816211:1089254471:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.816250:1089254509:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[13307:13307:0305/122720.816286:1089254544:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[13307:13307:0305/122720.816356:1089254617:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6945220065605591000\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.816403:1089254662:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.816443:1089254702:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 500\n[13307:13307:0305/122720.816481:1089254740:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.816518:1089254777:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dd0 with delay 60000\n[13307:13307:0305/122720.816566:1089254828:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[13307:13307:0305/122720.816607:1089254866:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.816656:1089254915:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.816790:1089255052: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: \"6945220065605591000\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.816901:1089255161:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0\n[13307:13307:0305/122720.816945:1089255205:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[13307:13307:0305/122720.817081:1089255348:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6945220065605591000\" 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[13307:13307:0305/122720.817146:1089255405:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6945220065605591000\"\n[13307:13307:0305/122720.817187:1089255446:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.817229:1089255488:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.817268:1089255527:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 1200000\n[13307:13307:0305/122720.817312:1089255571:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.817437:1089255697:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.817479:1089255738:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.817518:1089255777:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[13307:13307:0305/122720.817573:1089255832: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[13307:13307:0305/122720.817622:1089255880:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[13307:13307:0305/122720.817689:1089255948:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0\n[13307:13307:0305/122720.817736:1089255995:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.817789:1089256048:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e30 with delay 10000\n[13307:13307:0305/122720.817835:1089256093:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[13307:13307:0305/122720.817869:1089256128:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.817924:1089256185:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.817973:1089256248:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0\n[13307:13307:0305/122720.818027:1089256285:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50\n[13307:13307:0305/122720.818123:1089256383: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[13307:13307:0305/122720.818397:1089256656:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e30\n[13307:13307:0305/122720.819393:1089257652: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 (4 ms)\n[27/28] InvalidationClientImplTest.NoRegistrationSummary (4 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[13307:13307:0305/122720.819960:1089258220:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c90 with delay 0\n[13307:13307:0305/122720.820036:1089258295:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[13307:13307:0305/122720.820267:1089258530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0\n[13307:13307:0305/122720.820321:1089258580:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c90\n[13307:13307:0305/122720.820361:1089258619:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70\n[13307:13307:0305/122720.820429:1089258689:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[13307:13307:0305/122720.820492:1089258752:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[13307:13307:0305/122720.820536:1089258794:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[13307:13307:0305/122720.820574:1089258834:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[13307:13307:0305/122720.820614:1089258876:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0\n[13307:13307:0305/122720.820654:1089258912:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70\n[13307:13307:0305/122720.820688:1089258947:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[13307:13307:0305/122720.820730:1089258990:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424\n[13307:13307:0305/122720.820770:1089259029:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[13307:13307:0305/122720.820807:1089259065:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[13307:13307:0305/122720.820876:1089259137:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"7350534832621163732\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[13307:13307:0305/122720.820918:1089259177:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[13307:13307:0305/122720.820956:1089259216:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 500\n[13307:13307:0305/122720.821014:1089259274:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424\n[13307:13307:0305/122720.821054:1089259314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 60000\n[13307:13307:0305/122720.821108:1089259371:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70\n[13307:13307:0305/122720.821149:1089259409:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.821203:1089259462:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[13307:13307:0305/122720.821338:1089259600: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: \"7350534832621163732\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[13307:13307:0305/122720.821450:1089259709:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b70 with delay 0\n[13307:13307:0305/122720.821488:1089259749:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70\n[13307:13307:0305/122720.821617:1089259876:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"7350534832621163732\" 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[13307:13307:0305/122720.821678:1089259937:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"7350534832621163732\"\n[13307:13307:0305/122720.821726:1089259986:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[13307:13307:0305/122720.821789:1089260048:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[13307:13307:0305/122720.821830:1089260089:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 1200000\n[13307:13307:0305/122720.821876:1089260135:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[13307:13307:0305/122720.822010:1089260269:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.822052:1089260311:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[13307:13307:0305/122720.822096:1089260355:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[13307:13307:0305/122720.822153:1089260412: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[13307:13307:0305/122720.822200:1089260458:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[13307:13307:0305/122720.822266:1089260525:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0\n[13307:13307:0305/122720.822311:1089260570:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[13307:13307:0305/122720.822350:1089260609:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c90 with delay 10000\n[13307:13307:0305/122720.822387:1089260645:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[13307:13307:0305/122720.822420:1089260679:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[13307:13307:0305/122720.822871:1089261145:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c90\n[13307:13307:0305/122720.824126:1089262385:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000ac0\n[13307:13307:0305/122720.850039:1089288299:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000a50\n[13307:13307:0305/122720.850116:1089288376:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.850182:1089288442:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[13307:13307:0305/122720.850231:1089288490:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[13307:13307:0305/122720.850433:1089288699: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[13307:13307:0305/122720.850499:1089288759:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424\n[13307:13307:0305/122720.850550:1089288810:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000ac0 with delay 500\n[13307:13307:0305/122720.850596:1089288855:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[13307:13307:0305/122720.850634:1089288895:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000c90 with delay 1200000\n[13307:13307:0305/122720.850685:1089288944:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000ac0\n[13307:13307:0305/122720.850722:1089288984:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.850798:1089289058:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[13307:13307:0305/122720.850836:1089289096:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[13307:13307:0305/122720.851089:1089289349: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 (33 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (33 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "04ddf23a9e5fe7cb067f9c892df540f5bfb2fce6", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43685b6db6321911", "server_versions": [ "4143-92e279d" ], "started_ts": "2019-03-05T20:27:11.652703", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:linux_chromium_msan_rel_ng", "buildnumber:1394", "cpu:x86-64", "data:8919f9dfee252bbf12890a7dcae993aa5ea53274", "gerrit:https://chromium-review.googlesource.com/c/1504002/1", "gpu:none", "master:tryserver.chromium.linux", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "patch_project:chromium/src", "pool:Chrome", "priority:30", "project:chromium", "purpose:ManualTS", "purpose:luci", "purpose:pre-commit", "service_account:none", "slavename:swarm1908-c4", "spec_name:chromium.try:linux_chromium_msan_rel_ng", "stepname:cacheinvalidation_unittests (with patch)", "swarming.pool.template:none", "swarming.pool.version:8320f0eb3bee01bb14d5241351722197b808dc6a", "user:None" ], "task_id": "43685b6db6321910", "try_number": "1" } ] }