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-q1nf" ] }, { "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": [ "4201-b04f7f8" ] }, { "key": "zone", "value": [ "us", "us-west", "us-west1", "us-west1-a" ] } ], "bot_id": "gce-trusty-e833d7b0-us-west1-a-q1nf", "bot_version": "51d929b905e4fffb3652f17e0ff8dceb0f7077275d215d276fb6c5a2f238b3f7", "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-19T00:09:13.476483", "costs_usd": [ 0.0019201292304506397 ], "created_ts": "2019-03-18T23:49:31.585645", "duration": 2.8290979862213135, "modified_ts": "2019-03-19T00:09:13.476483", "name": "cacheinvalidation_unittests (with patch)/Ubuntu-14.04/207d3613fb/linux_chromium_msan_rel_ng/1401", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n MSAN_OPTIONS=symbolize=0 handle_abort=1\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioICnQrj/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[4737:4737:0318/170911.070584:12357189640:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0\n[4737:4737:0318/170911.070654:12357189711:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80\n[4737:4737:0318/170911.071052:12357190116: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[4737:4737:0318/170911.071136:12357190187:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424\n[4737:4737:0318/170911.071183:12357190238:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 500\n[4737:4737:0318/170911.071239:12357190290:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b90\n[4737:4737:0318/170911.071361:12357190413:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[4737:4737:0318/170911.071408:12357190462:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (1 ms)\n[1/28] ProtocolHandlerTest.TokenMissing (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[4737:4737:0318/170911.071943:12357191000:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 0\n[4737:4737:0318/170911.071998:12357191057:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b90\n[4737:4737:0318/170911.072062:12357191114:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424\n[4737:4737:0318/170911.072106:12357191156:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 500\n[4737:4737:0318/170911.072158:12357191215:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b80\n[4737:4737:0318/170911.072274:12357191332:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[4737:4737:0318/170911.072359:12357191410: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[4737:4737:0318/170911.072461:12357191517: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[4737:4737:0318/170911.072619:12357191681: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[4737:4737:0318/170911.072780:12357191834: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[4737:4737:0318/170911.073302:12357192354:INFO:protocol-handler.cc(139)] Incoming message: { }\n[4737:4737:0318/170911.073348:12357192404:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[4737:4737:0318/170911.073396:12357192448:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms)\n[3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[4737:4737:0318/170911.073696:12357192753:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 369177624 with a delay 10000, Now = 0\n[4737:4737:0318/170911.073749:12357192803:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10\n[4737:4737:0318/170911.073805:12357192862:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0\n[4737:4737:0318/170911.073862:12357192920:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[4737:4737:0318/170911.073915:12357192968:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 10000\n[4737:4737:0318/170911.073957:12357193013:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000a00 with delay 60\n[4737:4737:0318/170911.074007:12357193057:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x701000000a00\n[4737:4737:0318/170911.074040:12357193090:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[4737:4737:0318/170911.074073:12357193123:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 70000\n[4737:4737:0318/170911.074106:12357193156:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000009f0 with delay 60\n[4737:4737:0318/170911.074140:12357193190:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000009f0\n[4737:4737:0318/170911.074183:12357193233:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[4737:4737:0318/170911.074216:12357193266:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 130000\n[4737:4737:0318/170911.074249:12357193299:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x701000000a00 with delay 60\n[4737:4737:0318/170911.074284:12357193340:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x701000000a00\n[4737:4737:0318/170911.074323:12357193373:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[4737:4737:0318/170911.074355:12357193405:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 190000\n[4737:4737:0318/170911.074388:12357193438:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000009f0 with delay 60\n[4737:4737:0318/170911.074422:12357193481:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000009f0\n[4737:4737:0318/170911.074463:12357193513:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[4737:4737:0318/170911.074495:12357193545:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 250000\n[4737:4737:0318/170911.074527:12357193577:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x701000000a00 with delay 60\n[4737:4737:0318/170911.074561:12357193611:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x701000000a00\n[4737:4737:0318/170911.074593:12357193643:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[4737:4737:0318/170911.074624:12357193674:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 310000\n[4737:4737:0318/170911.074656:12357193706:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000009f0 with delay 60\n[4737:4737:0318/170911.074690:12357193740:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000009f0\n[4737:4737:0318/170911.074722:12357193772:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[4737:4737:0318/170911.074758:12357193808:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 370000\n[4737:4737:0318/170911.074792:12357193842:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x701000000a00 with delay 60\n[4737:4737:0318/170911.074833:12357193884:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x701000000a00\n[4737:4737:0318/170911.074882:12357193940:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (3 ms)\n[4/28] RecurringTaskTest.PeriodicTask (3 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[4737:4737:0318/170911.076135:12357195188:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 369177440 with a delay 10000, Now = 0\n[4737:4737:0318/170911.076194:12357195245:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000a00 with delay 10\n[4737:4737:0318/170911.076233:12357195289:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000a00\n[4737:4737:0318/170911.076280:12357195336:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[4737:4737:0318/170911.076328:12357195378:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 50000, Now = 10000\n[4737:4737:0318/170911.076364:12357195414:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 50\n[4737:4737:0318/170911.076403:12357195464:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000009f0\n[4737:4737:0318/170911.076469:12357195521:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[4737:4737:0318/170911.076508:12357195561:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 149000, Now = 60000\n[4737:4737:0318/170911.076546:12357195602:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x701000000a00 with delay 149\n[4737:4737:0318/170911.076608:12357195660:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x701000000a00\n[4737:4737:0318/170911.076650:12357195700:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[4737:4737:0318/170911.076685:12357195741:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 248000, Now = 210000\n[4737:4737:0318/170911.076737:12357195788:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000009f0 with delay 248\n[4737:4737:0318/170911.076793:12357195850:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000009f0\n[4737:4737:0318/170911.076852:12357195903:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[4737:4737:0318/170911.076888:12357195946:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 446000, Now = 460000\n[4737:4737:0318/170911.076938:12357195995:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x701000000a00 with delay 446\n[4737:4737:0318/170911.077025:12357196076:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x701000000a00\n[4737:4737:0318/170911.077061:12357196114:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[4737:4737:0318/170911.077099:12357196149:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 842000, Now = 910000\n[4737:4737:0318/170911.077136:12357196187:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000009f0 with delay 842\n[4737:4737:0318/170911.077205:12357196255:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000009f0\n[4737:4737:0318/170911.077238:12357196287:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[4737:4737:0318/170911.077278:12357196333:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 1040000, Now = 1760000\n[4737:4737:0318/170911.077317:12357196367:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x701000000a00 with delay 1040\n[4737:4737:0318/170911.077376:12357196426:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x701000000a00\n[4737:4737:0318/170911.077408:12357196458:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[4737:4737:0318/170911.077448:12357196498:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 1040000, Now = 2800000\n[4737:4737:0318/170911.077484:12357196534:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000009f0 with delay 1040\n[4737:4737:0318/170911.077543:12357196593:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000009f0\n[4737:4737:0318/170911.077575:12357196624:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms)\n[5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[4737:4737:0318/170911.078854:12357197912:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 369177480 with a delay 10000, Now = 0\n[4737:4737:0318/170911.078906:12357197957:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10\n[4737:4737:0318/170911.078958:12357198011:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0\n[4737:4737:0318/170911.078998:12357198054:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[4737:4737:0318/170911.079052:12357198107:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 369177480 with a delay 10000, Now = 10000\n[4737:4737:0318/170911.079098:12357198149:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 10\n[4737:4737:0318/170911.079140:12357198203:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000009f0\n[4737:4737:0318/170911.079196:12357198253:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (2 ms)\n[6/28] RecurringTaskTest.OneShotTask (2 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[4737:4737:0318/170911.080496:12357199551:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000009f0 with delay 920\n[4737:4737:0318/170911.080564:12357199614:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.080949:12357199999:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000009f0 with delay 45000\n[4737:4737:0318/170911.082155:12357201206: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[4737:4737:0318/170911.082308:12357201358:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 990\n[4737:4737:0318/170911.082375:12357201426:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.082423:12357201483:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.082500:12357201549:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.082535:12357201584:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.082595:12357201644:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.082628:12357201678:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.082689:12357201738:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.082722:12357201772:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.082782:12357201834:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.082818:12357201868:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.082878:12357201927:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.082914:12357201965:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x701000000a00 with delay 54000\n[4737:4737:0318/170911.084551:12357203601:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000000a00\n[4737:4737:0318/170911.084590:12357203640:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.084658:12357203707:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x701000000a00\n[4737:4737:0318/170911.084691:12357203741:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.084752:12357203801:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x701000000a00\n[4737:4737:0318/170911.084785:12357203837:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.084848:12357203898:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x701000000a00\n[4737:4737:0318/170911.084882:12357203932:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.084942:12357203991:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x701000000a00\n[4737:4737:0318/170911.084993:12357204042:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.085053:12357204103:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x701000000a00\n[4737:4737:0318/170911.085087:12357204136:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.085146:12357204196:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x701000000a00\n[4737:4737:0318/170911.085183:12357204233:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000009f0 with delay 54000\n[4737:4737:0318/170911.086804:12357205854:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.086844:12357205893:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.086904:12357205954:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.086937:12357205987:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.086997:12357206046:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.087030:12357206079:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.087090:12357206139:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.087123:12357206172:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.087183:12357206232:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.087216:12357206266:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.087276:12357206330:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.087314:12357206364:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.087374:12357206423:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.087407:12357206457:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x701000000a00 with delay 54000\n[4737:4737:0318/170911.089030:12357208080:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x701000000a00\n[4737:4737:0318/170911.089068:12357208118:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.089129:12357208178:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x701000000a00\n[4737:4737:0318/170911.089163:12357208212:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.089222:12357208272:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x701000000a00\n[4737:4737:0318/170911.089261:12357208311:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.089325:12357208375:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x701000000a00\n[4737:4737:0318/170911.089359:12357208408:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.089419:12357208475:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x701000000a00\n[4737:4737:0318/170911.089460:12357208509:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.089520:12357208569:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x701000000a00\n[4737:4737:0318/170911.089553:12357208602:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x701000000a00 with delay 1000\n[4737:4737:0318/170911.089613:12357208662:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x701000000a00\n[4737:4737:0318/170911.089645:12357208695:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000009f0 with delay 54000\n[4737:4737:0318/170911.091255:12357210305:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.091296:12357210346:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.091361:12357210411:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.091395:12357210444:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.091461:12357210511:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.091495:12357210544:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.091555:12357210604:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.091588:12357210637:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.091648:12357210697:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.091681:12357210730:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.091741:12357210790:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.091774:12357210824:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000009f0 with delay 1000\n[4737:4737:0318/170911.091836:12357210886:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000009f0\n[4737:4737:0318/170911.091869:12357210919:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x701000000a00 with delay 54000\n[4737:4737:0318/170911.093530:12357212581: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[4736:4736:0318/170911.044905:12357163960:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0\n[4736:4736:0318/170911.045268:12357164326:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80\n[4736:4736:0318/170911.045634:12357164685: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[4736:4736:0318/170911.045700:12357164752:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424\n[4736:4736:0318/170911.045747:12357164798:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 500\n[4736:4736:0318/170911.045808:12357164860:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10\n[4736:4736:0318/170911.046102:12357165155: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 (2 ms)\n[9/28] ProtocolHandlerTest.SendInitializeOnly (2 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[4736:4736:0318/170911.047375:12357166428: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[4736:4736:0318/170911.047891:12357166944:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[4736:4736:0318/170911.047967:12357167023:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b40 with delay 0\n[4736:4736:0318/170911.048020:12357167076:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0\n[4736:4736:0318/170911.048094:12357167145:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b00 with delay 0\n[4736:4736:0318/170911.048140:12357167190:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ab0 with delay 0\n[4736:4736:0318/170911.048184:12357167235:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[4736:4736:0318/170911.048601:12357167653:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[4736:4736:0318/170911.048759:12357167811: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[4736:4736:0318/170911.048819:12357167870:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424\n[4736:4736:0318/170911.048866:12357167918:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c60 with delay 500\n[4736:4736:0318/170911.048910:12357167959:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b40\n[4736:4736:0318/170911.048951:12357168024:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0\n[4736:4736:0318/170911.049021:12357168071:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b00\n[4736:4736:0318/170911.049063:12357168112:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ab0\n[4736:4736:0318/170911.049099:12357168160:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[4736:4736:0318/170911.049167:12357168217:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[4736:4736:0318/170911.049224:12357168274:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c60\n[4736:4736:0318/170911.049446:12357168496:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[4736:4736:0318/170911.050828:12357169882: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[4736:4736:0318/170911.052582:12357171639: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[4736:4736:0318/170911.053286:12357172349: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[4736:4736:0318/170911.053392:12357172443: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[4736:4736:0318/170911.053514:12357172566: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[4736:4736:0318/170911.053626:12357172677: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[4736:4736:0318/170911.054170:12357173222: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[4736:4736:0318/170911.054309:12357173360: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[4736:4736:0318/170911.054823:12357173874: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[4736:4736:0318/170911.055333:12357174385: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[4736:4736:0318/170911.055411:12357174479:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a40 with delay 0\n[4736:4736:0318/170911.055471:12357174535:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a40\n[4736:4736:0318/170911.055577:12357174630: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[4736:4736:0318/170911.055637:12357174688:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424\n[4736:4736:0318/170911.055676:12357174735:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a50 with delay 500\n[4736:4736:0318/170911.055736:12357174790:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[4736:4736:0318/170911.055781:12357174832:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (46 ms)\n[16/28] ProtocolHandlerTest.ConfigMessage (46 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[4736:4736:0318/170911.101617:12357220671:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.ErrorMessage (0 ms)\n[17/28] ProtocolHandlerTest.ErrorMessage (0 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[4736:4736:0318/170911.102180:12357221238:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.TokenMismatch (1 ms)\n[18/28] ProtocolHandlerTest.TokenMismatch (1 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[4734:4734:0318/170911.016486:12357135542:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c80 with delay 0\n[4734:4734:0318/170911.016878:12357135938:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.017261:12357136314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[4734:4734:0318/170911.017311:12357136365:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c80\n[4734:4734:0318/170911.017352:12357136402:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[4734:4734:0318/170911.017446:12357136497:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.017539:12357136590:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0\n[4734:4734:0318/170911.017588:12357136638:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0\n[4734:4734:0318/170911.017622:12357136673:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.017676:12357136727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0\n[4734:4734:0318/170911.017719:12357136769:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50\n[4734:4734:0318/170911.017766:12357136817:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.017810:12357136861:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.017849:12357136900:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0\n[4734:4734:0318/170911.017888:12357136938:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0\n[4734:4734:0318/170911.017978:12357137028:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7205043523080705347\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.018027:12357137079:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.018074:12357137125:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 500\n[4734:4734:0318/170911.018115:12357137166:INFO:recurring-task.cc(55)] [Retry] Scheduling 9224 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.018163:12357137213:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e10 with delay 60000\n[4734:4734:0318/170911.018220:12357137280:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[4734:4734:0318/170911.018285:12357137335:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.018361:12357137415:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.018577:12357137628: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: \"-7205043523080705347\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.018836:12357137887:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e50 with delay 0\n[4734:4734:0318/170911.018892:12357137943:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50\n[4734:4734:0318/170911.019042:12357138093:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7205043523080705347\" 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[4734:4734:0318/170911.019114:12357138164:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7205043523080705347\"\n[4734:4734:0318/170911.019154:12357138204:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.019197:12357138253:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.019250:12357138300:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e90 with delay 1200000\n[4734:4734:0318/170911.019305:12357138356:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.019484:12357138539:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.019533:12357138588:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.019574:12357138630:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ea0 with delay 0\n[4734:4734:0318/170911.019678:12357138729: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[4734:4734:0318/170911.019739:12357138793:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ea0\n[4734:4734:0318/170911.019837:12357138888:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 0\n[4734:4734:0318/170911.019887:12357138938:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.019926:12357138977:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c80 with delay 10000\n[4734:4734:0318/170911.019965:12357139015:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0\n[4734:4734:0318/170911.019999:12357139050: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[4734:4734:0318/170911.020877:12357139928:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[4734:4734:0318/170911.020941:12357139991:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)\n[20/28] InvalidationClientImplTest.GenerateNonce (1 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[4734:4734:0318/170911.021581:12357140634:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0\n[4734:4734:0318/170911.021646:12357140696:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.021943:12357140994:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0\n[4734:4734:0318/170911.021997:12357141048:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80\n[4734:4734:0318/170911.022038:12357141088:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0\n[4734:4734:0318/170911.022107:12357141158:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.022176:12357141232:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[4734:4734:0318/170911.022240:12357141290:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[4734:4734:0318/170911.022275:12357141329:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.022324:12357141374:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0\n[4734:4734:0318/170911.022363:12357141418:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0\n[4734:4734:0318/170911.022406:12357141456:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.022461:12357141512:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.022510:12357141564:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[4734:4734:0318/170911.022554:12357141604:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[4734:4734:0318/170911.022639:12357141692:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"7458590634550464377\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.022688:12357141739:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9224 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.022726:12357141779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 500\n[4734:4734:0318/170911.022765:12357141816:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.022810:12357141861:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 60000\n[4734:4734:0318/170911.022864:12357141915:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0\n[4734:4734:0318/170911.022901:12357141954:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.022952:12357142002:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.023095:12357142147: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: \"7458590634550464377\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.023240:12357142291:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 0\n[4734:4734:0318/170911.023283:12357142338:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0\n[4734:4734:0318/170911.023420:12357142482:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"7458590634550464377\" 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[4734:4734:0318/170911.023495:12357142546:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"7458590634550464377\"\n[4734:4734:0318/170911.023544:12357142594:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.023587:12357142638:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.023624:12357142677:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f10 with delay 1200000\n[4734:4734:0318/170911.023666:12357142716:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.023805:12357142857:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.023846:12357142897:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.023888:12357142938:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[4734:4734:0318/170911.023946:12357142996: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[4734:4734:0318/170911.024005:12357143055:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[4734:4734:0318/170911.024079:12357143130:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0\n[4734:4734:0318/170911.024133:12357143186:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.024175:12357143225:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e80 with delay 10000\n[4734:4734:0318/170911.024213:12357143263:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40\n[4734:4734:0318/170911.024253:12357143303:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.024340:12357143391:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f40 with delay 0\n[4734:4734:0318/170911.024382:12357143432:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f40\n[4734:4734:0318/170911.024443:12357143500:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[4734:4734:0318/170911.024497:12357143547:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[4734:4734:0318/170911.024545:12357143595:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[4734:4734:0318/170911.024643:12357143694:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9224 with a delay 500000, Now = 211469424\n[4734:4734:0318/170911.024686:12357143738:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500\n[4734:4734:0318/170911.024729:12357143782:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424\n[4734:4734:0318/170911.024767:12357143817:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f30 with delay 60000\n[4734:4734:0318/170911.024825:12357143881:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[4734:4734:0318/170911.024869:12357143919:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.024924:12357143975:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.024961:12357144032:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[4734:4734:0318/170911.025166:12357144220: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[4734:4734:0318/170911.025278:12357144329:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.025367:12357144424:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f20 with delay 0\n[4734:4734:0318/170911.025419:12357144479:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[4734:4734:0318/170911.025670:12357144724: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[4734:4734:0318/170911.025792:12357144847: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[4734:4734:0318/170911.025898:12357144957:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[4734:4734:0318/170911.026046:12357145100:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[4734:4734:0318/170911.026149:12357145203:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[4734:4734:0318/170911.026482:12357145533:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e80\n[ OK ] InvalidationClientImplTest.Register (6 ms)\n[21/28] InvalidationClientImplTest.Register (6 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[4734:4734:0318/170911.028277:12357147330:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dc0 with delay 0\n[4734:4734:0318/170911.028344:12357147394:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.028712:12357147763:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0\n[4734:4734:0318/170911.028766:12357147816:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000dc0\n[4734:4734:0318/170911.028809:12357147859:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30\n[4734:4734:0318/170911.028885:12357147938:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.028956:12357148022:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0\n[4734:4734:0318/170911.029024:12357148077:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40\n[4734:4734:0318/170911.029066:12357148116:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.029103:12357148156:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0\n[4734:4734:0318/170911.029143:12357148197:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30\n[4734:4734:0318/170911.029195:12357148246:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.029254:12357148305:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.029311:12357148361:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0\n[4734:4734:0318/170911.029349:12357148399:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40\n[4734:4734:0318/170911.029424:12357148482:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4727764432818465460\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.029476:12357148527:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.029523:12357148574:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 500\n[4734:4734:0318/170911.029562:12357148613:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.029598:12357148649:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ba0 with delay 60000\n[4734:4734:0318/170911.029649:12357148700:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30\n[4734:4734:0318/170911.029688:12357148738:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.029740:12357148790:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.029878:12357148929: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: \"-4727764432818465460\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.029996:12357149047:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c30 with delay 0\n[4734:4734:0318/170911.030037:12357149088:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30\n[4734:4734:0318/170911.030173:12357149223:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4727764432818465460\" 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[4734:4734:0318/170911.030240:12357149298:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4727764432818465460\"\n[4734:4734:0318/170911.030294:12357149345:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.030337:12357149390:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.030379:12357149429:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000\n[4734:4734:0318/170911.030418:12357149483:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.030558:12357149608:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.030597:12357149649:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.030634:12357149684:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0\n[4734:4734:0318/170911.030697:12357149750: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[4734:4734:0318/170911.030750:12357149802:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40\n[4734:4734:0318/170911.030835:12357149886:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f70 with delay 0\n[4734:4734:0318/170911.030888:12357149938:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.030924:12357149980:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000dc0 with delay 10000\n[4734:4734:0318/170911.030966:12357150016:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f70\n[4734:4734:0318/170911.031005:12357150055:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.031064:12357150115:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.031129:12357150180:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 0\n[4734:4734:0318/170911.031169:12357150220:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f70\n[4734:4734:0318/170911.031399:12357150450: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[4734:4734:0318/170911.031505:12357150556: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[4734:4734:0318/170911.031589:12357150640: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[4734:4734:0318/170911.031744:12357150798: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[4734:4734:0318/170911.031851:12357150901: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[4734:4734:0318/170911.031945:12357150996:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f70 with delay 0\n[4734:4734:0318/170911.031986:12357151037:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f40 with delay 0\n[4734:4734:0318/170911.032025:12357151075:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f50 with delay 0\n[4734:4734:0318/170911.032065:12357151116:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f70\n[4734:4734:0318/170911.032121:12357151172:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424\n[4734:4734:0318/170911.032162:12357151215:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000c30 with delay 500\n[4734:4734:0318/170911.032206:12357151257:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f40\n[4734:4734:0318/170911.032260:12357151313:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f50\n[4734:4734:0318/170911.032316:12357151366:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000000c30\n[4734:4734:0318/170911.032360:12357151411:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.032421:12357151481:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.032471:12357151522:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[4734:4734:0318/170911.032661:12357151712: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 (6 ms)\n[22/28] InvalidationClientImplTest.Invalidations (6 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[4734:4734:0318/170911.033472:12357152525:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000eb0 with delay 0\n[4734:4734:0318/170911.033541:12357152592:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.033775:12357152833:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[4734:4734:0318/170911.033828:12357152880:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000eb0\n[4734:4734:0318/170911.033870:12357152920:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[4734:4734:0318/170911.033940:12357152994:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.034004:12357153055:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[4734:4734:0318/170911.034050:12357153100:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[4734:4734:0318/170911.034085:12357153136:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.034122:12357153174:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[4734:4734:0318/170911.034161:12357153211:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[4734:4734:0318/170911.034196:12357153246:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.034246:12357153297:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.034295:12357153354:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0\n[4734:4734:0318/170911.034352:12357153411:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20\n[4734:4734:0318/170911.034467:12357153531:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1256292921504706621\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.034529:12357153583:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.034576:12357153626:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500\n[4734:4734:0318/170911.034619:12357153672:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.034658:12357153709:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d40 with delay 60000\n[4734:4734:0318/170911.034709:12357153763:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[4734:4734:0318/170911.034759:12357153813:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.034816:12357153866:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.034959:12357154009: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: \"-1256292921504706621\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.035081:12357154132:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0\n[4734:4734:0318/170911.035122:12357154173:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[4734:4734:0318/170911.035259:12357154309:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1256292921504706621\" 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[4734:4734:0318/170911.035317:12357154370:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1256292921504706621\"\n[4734:4734:0318/170911.035361:12357154412:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.035404:12357154455:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.035454:12357154504:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 1200000\n[4734:4734:0318/170911.035493:12357154550:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.035650:12357154701:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.035690:12357154741:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.035729:12357154782:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0\n[4734:4734:0318/170911.035805:12357154858: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[4734:4734:0318/170911.035857:12357154907:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20\n[4734:4734:0318/170911.035931:12357154981:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 0\n[4734:4734:0318/170911.035977:12357155028:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.036014:12357155068:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000eb0 with delay 10000\n[4734:4734:0318/170911.036054:12357155104:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c20\n[4734:4734:0318/170911.036088:12357155142:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.036154:12357155207:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.036229:12357155285:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000c20 with delay 0\n[4734:4734:0318/170911.036279:12357155329:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000c20\n[4734:4734:0318/170911.036420:12357155482: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[4734:4734:0318/170911.036508:12357155560: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[4734:4734:0318/170911.036556:12357155606:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[4734:4734:0318/170911.036596:12357155647:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424\n[4734:4734:0318/170911.036634:12357155685:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500\n[4734:4734:0318/170911.036672:12357155728:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[4734:4734:0318/170911.036929:12357155980: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[4734:4734:0318/170911.037021:12357156072:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20\n[4734:4734:0318/170911.037063:12357156113:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.037140:12357156191:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.037178:12357156228:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[4734:4734:0318/170911.038380:12357157435: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[4734:4734:0318/170911.038771:12357157822: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[4734:4734:0318/170911.040456:12357159509:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[4734:4734:0318/170911.040525:12357159575:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.040778:12357159829:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[4734:4734:0318/170911.040821:12357159872:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[4734:4734:0318/170911.040862:12357159912:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[4734:4734:0318/170911.040931:12357159982:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.041016:12357160067:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0\n[4734:4734:0318/170911.041063:12357160113:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0\n[4734:4734:0318/170911.041097:12357160148:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.041137:12357160188:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0\n[4734:4734:0318/170911.041176:12357160226:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10\n[4734:4734:0318/170911.041211:12357160261:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.041258:12357160309:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.041296:12357160346:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0\n[4734:4734:0318/170911.041334:12357160384:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0\n[4734:4734:0318/170911.041406:12357160456:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1603052231409875050\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.041457:12357160508:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.041493:12357160546:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500\n[4734:4734:0318/170911.041532:12357160582:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.041573:12357160624:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 60000\n[4734:4734:0318/170911.041624:12357160675:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[4734:4734:0318/170911.041661:12357160711:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.041714:12357160764:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.041851:12357160904: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: \"1603052231409875050\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.041976:12357161028:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0\n[4734:4734:0318/170911.042017:12357161068:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10\n[4734:4734:0318/170911.042142:12357161192:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1603052231409875050\" 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[4734:4734:0318/170911.042201:12357161251:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1603052231409875050\"\n[4734:4734:0318/170911.042249:12357161299:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.042295:12357161346:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.042338:12357161388:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 1200000\n[4734:4734:0318/170911.042385:12357161439:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.042538:12357161589:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.042582:12357161635:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.042624:12357161678:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ae0 with delay 0\n[4734:4734:0318/170911.042690:12357161740: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[4734:4734:0318/170911.042743:12357161793:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ae0\n[4734:4734:0318/170911.042820:12357161870:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000009e0 with delay 0\n[4734:4734:0318/170911.042864:12357161914:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.042902:12357161953:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 10000\n[4734:4734:0318/170911.042941:12357161990:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000009e0\n[4734:4734:0318/170911.042974:12357162027:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.043036:12357162093:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.043099:12357162153:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000009e0 with delay 0\n[4734:4734:0318/170911.043141:12357162192:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000009e0\n[4734:4734:0318/170911.043268:12357162318: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[4734:4734:0318/170911.043342:12357162393: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[4734:4734:0318/170911.043381:12357162436:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[4734:4734:0318/170911.043715:12357162766:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000b50\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms)\n[24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[4734:4734:0318/170911.045327:12357164379:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d90 with delay 0\n[4734:4734:0318/170911.045396:12357164446:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.045712:12357164764:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[4734:4734:0318/170911.045765:12357164815:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d90\n[4734:4734:0318/170911.045807:12357164857:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70\n[4734:4734:0318/170911.045877:12357164927:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.045940:12357164991:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0\n[4734:4734:0318/170911.045984:12357165034:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50\n[4734:4734:0318/170911.046025:12357165079:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.046066:12357165117:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0\n[4734:4734:0318/170911.046110:12357165160:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70\n[4734:4734:0318/170911.046144:12357165195:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.046188:12357165240:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.046225:12357165287:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0\n[4734:4734:0318/170911.046274:12357165324:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50\n[4734:4734:0318/170911.046345:12357165396:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-9000685672725104912\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.046388:12357165438:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.046425:12357165484:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 500\n[4734:4734:0318/170911.046469:12357165520:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.046508:12357165558:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 60000\n[4734:4734:0318/170911.046558:12357165610:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70\n[4734:4734:0318/170911.046598:12357165650:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.046650:12357165701:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.046789:12357165839: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: \"-9000685672725104912\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.046900:12357165951:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e70 with delay 0\n[4734:4734:0318/170911.046945:12357166004:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70\n[4734:4734:0318/170911.047077:12357166130:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-9000685672725104912\" 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[4734:4734:0318/170911.047136:12357166186:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-9000685672725104912\"\n[4734:4734:0318/170911.047177:12357166227:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.047219:12357166275:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.047261:12357166314:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 1200000\n[4734:4734:0318/170911.047304:12357166354:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.047440:12357166493:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.047482:12357166538:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.047529:12357166580:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f50 with delay 0\n[4734:4734:0318/170911.047591:12357166646: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[4734:4734:0318/170911.047643:12357166697:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f50\n[4734:4734:0318/170911.047721:12357166774:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f60 with delay 0\n[4734:4734:0318/170911.047769:12357166822:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.047808:12357166858:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d90 with delay 10000\n[4734:4734:0318/170911.047849:12357166899:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f60\n[4734:4734:0318/170911.047883:12357166933:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.047940:12357166990:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f60 with delay 0\n[4734:4734:0318/170911.047977:12357167027:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f60\n[4734:4734:0318/170911.048029:12357167079:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[4734:4734:0318/170911.048091:12357167144:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424\n[4734:4734:0318/170911.048130:12357167180:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 500\n[4734:4734:0318/170911.048170:12357167221:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9224 with a delay 60000000, Now = 211469424\n[4734:4734:0318/170911.048209:12357167259:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 60000\n[4734:4734:0318/170911.048270:12357167321:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50\n[4734:4734:0318/170911.048311:12357167361:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.048358:12357167423:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.048417:12357167476:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[4734:4734:0318/170911.048567:12357167618: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[4734:4734:0318/170911.048652:12357167702:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.048705:12357167756:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f50 with delay 0\n[4734:4734:0318/170911.048748:12357167798:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50\n[4734:4734:0318/170911.048862:12357167912: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[4734:4734:0318/170911.048941:12357167994: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[4734:4734:0318/170911.049002:12357168052:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[4734:4734:0318/170911.049102:12357168152:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[4734:4734:0318/170911.049413:12357168464: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[4734:4734:0318/170911.051073:12357170125:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c20 with delay 0\n[4734:4734:0318/170911.051139:12357170190:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.051385:12357170437:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[4734:4734:0318/170911.051427:12357170489:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c20\n[4734:4734:0318/170911.051476:12357170526:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[4734:4734:0318/170911.051547:12357170598:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.051615:12357170666:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0\n[4734:4734:0318/170911.051664:12357170714:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20\n[4734:4734:0318/170911.051702:12357170752:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.051743:12357170794:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0\n[4734:4734:0318/170911.051781:12357170830:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50\n[4734:4734:0318/170911.051815:12357170865:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.051861:12357170911:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.051899:12357170950:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0\n[4734:4734:0318/170911.051943:12357170993:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20\n[4734:4734:0318/170911.052012:12357171063:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8208106377270690358\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.052058:12357171109:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.052097:12357171148:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 500\n[4734:4734:0318/170911.052135:12357171186:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.052175:12357171225:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c50 with delay 60000\n[4734:4734:0318/170911.052228:12357171284:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[4734:4734:0318/170911.052273:12357171323:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.052320:12357171370:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.052465:12357171516: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: \"8208106377270690358\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.052584:12357171635:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 0\n[4734:4734:0318/170911.052626:12357171677:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50\n[4734:4734:0318/170911.052754:12357171804:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8208106377270690358\" 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[4734:4734:0318/170911.052811:12357171862:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8208106377270690358\"\n[4734:4734:0318/170911.052852:12357171903:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.052894:12357171944:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.052933:12357171984:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000\n[4734:4734:0318/170911.052988:12357172040:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.053119:12357172170:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.053162:12357172213:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.053199:12357172249:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 0\n[4734:4734:0318/170911.053263:12357172314: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[4734:4734:0318/170911.053311:12357172361:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e20\n[4734:4734:0318/170911.053387:12357172437:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0\n[4734:4734:0318/170911.053444:12357172519:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.053508:12357172559:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 10000\n[4734:4734:0318/170911.053544:12357172594:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[4734:4734:0318/170911.053578:12357172628:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.053636:12357172686:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0\n[4734:4734:0318/170911.053676:12357172727:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50\n[4734:4734:0318/170911.053727:12357172782:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[4734:4734:0318/170911.053792:12357172842:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424\n[4734:4734:0318/170911.053830:12357172882:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000e20 with delay 500\n[4734:4734:0318/170911.053869:12357172919:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424\n[4734:4734:0318/170911.053906:12357172957:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000af0 with delay 60000\n[4734:4734:0318/170911.053970:12357173026:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000e20\n[4734:4734:0318/170911.054020:12357173070:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.054074:12357173125:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.054116:12357173166:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[4734:4734:0318/170911.054262:12357173313: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[4734:4734:0318/170911.054572:12357173626:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c20\n[4734:4734:0318/170911.055741:12357174791:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000c50\n[4734:4734:0318/170911.055790:12357174840:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000af0\n[4734:4734:0318/170911.055850:12357174902: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[4734:4734:0318/170911.055890:12357174942:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[4734:4734:0318/170911.055971:12357175022: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[4734:4734:0318/170911.056015:12357175066:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424\n[4734:4734:0318/170911.056053:12357175104:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c50 with delay 500\n[4734:4734:0318/170911.056091:12357175142:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424\n[4734:4734:0318/170911.056135:12357175186:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c20 with delay 60000\n[4734:4734:0318/170911.056189:12357175240:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000c50\n[4734:4734:0318/170911.056229:12357175288:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.056290:12357175340:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.056328:12357175379:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[4734:4734:0318/170911.056494:12357175550: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[4734:4734:0318/170911.058400:12357177453:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0\n[4734:4734:0318/170911.058478:12357177528:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.058706:12357177758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[4734:4734:0318/170911.058754:12357177807:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30\n[4734:4734:0318/170911.058796:12357177846:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[4734:4734:0318/170911.058866:12357177917:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.058927:12357177978:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[4734:4734:0318/170911.058970:12357178021:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[4734:4734:0318/170911.059006:12357178060:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.059049:12357178099:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0\n[4734:4734:0318/170911.059090:12357178140:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10\n[4734:4734:0318/170911.059125:12357178175:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.059171:12357178222:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.059211:12357178261:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[4734:4734:0318/170911.059255:12357178305:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[4734:4734:0318/170911.059332:12357178382:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"5319934619187797389\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.059376:12357178427:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.059415:12357178476:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 500\n[4734:4734:0318/170911.059462:12357178513:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.059505:12357178556:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dd0 with delay 60000\n[4734:4734:0318/170911.059556:12357178607:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[4734:4734:0318/170911.059593:12357178646:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.059644:12357178694:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.059795:12357178846: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: \"5319934619187797389\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.059908:12357178959:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0\n[4734:4734:0318/170911.059948:12357179000:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[4734:4734:0318/170911.060073:12357179126:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"5319934619187797389\" 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[4734:4734:0318/170911.060139:12357179189:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"5319934619187797389\"\n[4734:4734:0318/170911.060180:12357179231:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.060222:12357179278:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.060264:12357179319:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 1200000\n[4734:4734:0318/170911.060308:12357179359:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.060447:12357179500:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.060489:12357179540:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.060527:12357179578:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[4734:4734:0318/170911.060584:12357179634: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[4734:4734:0318/170911.060631:12357179681:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[4734:4734:0318/170911.060707:12357179758:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0\n[4734:4734:0318/170911.060753:12357179810:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.060796:12357179846:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e30 with delay 10000\n[4734:4734:0318/170911.060835:12357179885:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50\n[4734:4734:0318/170911.060869:12357179920:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.060926:12357179977:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.060999:12357180050:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0\n[4734:4734:0318/170911.061050:12357180101:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50\n[4734:4734:0318/170911.061151:12357180205: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[4734:4734:0318/170911.061456:12357180507:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e30\n[4734:4734:0318/170911.062505:12357181555: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[4734:4734:0318/170911.063132:12357182184:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c90 with delay 0\n[4734:4734:0318/170911.063204:12357182263:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[4734:4734:0318/170911.063470:12357182521:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0\n[4734:4734:0318/170911.063514:12357182564:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c90\n[4734:4734:0318/170911.063550:12357182600:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70\n[4734:4734:0318/170911.063632:12357182682:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[4734:4734:0318/170911.063691:12357182742:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[4734:4734:0318/170911.063740:12357182790:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[4734:4734:0318/170911.063774:12357182825:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[4734:4734:0318/170911.063814:12357182865:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0\n[4734:4734:0318/170911.063859:12357182909:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70\n[4734:4734:0318/170911.063894:12357182944:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[4734:4734:0318/170911.063932:12357182983:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424\n[4734:4734:0318/170911.063972:12357183022:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0\n[4734:4734:0318/170911.064013:12357183063:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0\n[4734:4734:0318/170911.064085:12357183136:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4101616717100667104\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[4734:4734:0318/170911.064125:12357183181:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[4734:4734:0318/170911.064166:12357183216:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 500\n[4734:4734:0318/170911.064205:12357183256:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424\n[4734:4734:0318/170911.064251:12357183302:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 60000\n[4734:4734:0318/170911.064303:12357183354:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70\n[4734:4734:0318/170911.064341:12357183391:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.064393:12357183446:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[4734:4734:0318/170911.064540:12357183591: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: \"-4101616717100667104\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[4734:4734:0318/170911.064654:12357183705:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b70 with delay 0\n[4734:4734:0318/170911.064696:12357183747:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70\n[4734:4734:0318/170911.064826:12357183877:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4101616717100667104\" 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[4734:4734:0318/170911.064888:12357183938:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4101616717100667104\"\n[4734:4734:0318/170911.064929:12357183981:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[4734:4734:0318/170911.064991:12357184042:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[4734:4734:0318/170911.065033:12357184084:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 1200000\n[4734:4734:0318/170911.065075:12357184126:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[4734:4734:0318/170911.065208:12357184259:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.065257:12357184308:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424\n[4734:4734:0318/170911.065298:12357184349:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0\n[4734:4734:0318/170911.065357:12357184408: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[4734:4734:0318/170911.065405:12357184456:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0\n[4734:4734:0318/170911.065484:12357184534:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0\n[4734:4734:0318/170911.065532:12357184583:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424\n[4734:4734:0318/170911.065572:12357184622:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c90 with delay 10000\n[4734:4734:0318/170911.065610:12357184660:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10\n[4734:4734:0318/170911.065644:12357184695:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[4734:4734:0318/170911.065926:12357184977:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c90\n[4734:4734:0318/170911.067135:12357186185:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000ac0\n[4734:4734:0318/170911.094105:12357213157:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000a50\n[4734:4734:0318/170911.094181:12357213232:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.094258:12357213311:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[4734:4734:0318/170911.094301:12357213352:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[4734:4734:0318/170911.094513:12357213567: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[4734:4734:0318/170911.094563:12357213614:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424\n[4734:4734:0318/170911.094605:12357213655:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000ac0 with delay 500\n[4734:4734:0318/170911.094649:12357213699:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[4734:4734:0318/170911.094687:12357213737:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000c90 with delay 1200000\n[4734:4734:0318/170911.094742:12357213792:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000ac0\n[4734:4734:0318/170911.094779:12357213830:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.094860:12357213911:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[4734:4734:0318/170911.094898:12357213949:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[4734:4734:0318/170911.095138:12357214189:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: \"2\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } performance_counter: { name: \"SentMessageType.INITIALIZE\" value: 1 } performance_counter: { name: \"SentMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOKEN_CONTROL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ListenerEventType.REISSUE_REGISTRATIONS\" value: 1 } performance_counter: { name: \"ClientErrorType.PERSISTENT_READ_FAILURE\" value: 1 } server_registration_summary_requested: false } }\n[ OK ] InvalidationClientImplTest.Heartbeats (34 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (34 ms)\nSUCCESS: all tests passed.\nTests took 1 seconds.\n", "outputs_ref": { "isolated": "28b843cdd3dc7bcc6dc37ae2fbee458d416562c4", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43ac075953409a11", "server_versions": [ "4201-b04f7f8" ], "started_ts": "2019-03-19T00:08:58.667144", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:linux_chromium_msan_rel_ng", "buildnumber:1401", "cpu:x86-64", "data:207d3613fb200ae042ece9901b317ffc76c032f9", "gerrit:https://chromium-review.googlesource.com/c/1528472/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:b6a93b27c04f0be59a826de8428184e97540ac64", "user:None" ], "task_id": "43ac075953409a10", "try_number": "1" } ] }