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-canary-e973df7c-us-central1-c-llnz" ] }, { "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-central", "us-central1", "us-central1-c" ] } ], "bot_id": "gce-trusty-canary-e973df7c-us-central1-c-llnz", "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-19T10:58:49.179348", "cost_saved_usd": 0.0007240981076118765, "created_ts": "2019-03-19T13:47:44.954710", "deduped_from": "43ae6c01baea8711", "duration": 0.7692699432373047, "modified_ts": "2019-03-19T13:47:44.984561", "name": "cacheinvalidation_unittests/Ubuntu-14.04/41e85c64ae/Linux ASan LSan Tests (1)/58501", "output": "Additional test environment:\n ASAN_OPTIONS=symbolize=0 handle_abort=1\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioNkRMl9/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[17778:17778:0319/035847.951534:16168146589:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0\n[17778:17778:0319/035847.951599:16168146659:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0\n[17778:17778:0319/035847.951815:16168146868: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[17778:17778:0319/035847.951866:16168146919:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24104 with a delay 500000, Now = 210919424\n[17778:17778:0319/035847.951900:16168146952:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d10 with delay 500\n[17778:17778:0319/035847.951965:16168147024:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d10\n[17778:17778:0319/035847.952037:16168147094:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[17778:17778:0319/035847.952076:16168147129: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[17778:17778:0319/035847.952519:16168147576:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002290 with delay 0\n[17778:17778:0319/035847.952558:16168147610:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002290\n[17778:17778:0319/035847.952589:16168147641:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 29096 with a delay 500000, Now = 210919424\n[17778:17778:0319/035847.952632:16168147687:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000022b0 with delay 500\n[17778:17778:0319/035847.952692:16168147745:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000022b0\n[17778:17778:0319/035847.952775:16168147830:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[17778:17778:0319/035847.952855:16168147909: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[17778:17778:0319/035847.952921:16168147974: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[17778:17778:0319/035847.953056:16168148109: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[17778:17778:0319/035847.953186:16168148239: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[17778:17778:0319/035847.953654:16168148708:INFO:protocol-handler.cc(139)] Incoming message: { }\n[17778:17778:0319/035847.953686:16168148742:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[17778:17778:0319/035847.953716:16168148768: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[17778:17778:0319/035847.953958:16168149014:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1628921960 with a delay 10000, Now = 0\n[17778:17778:0319/035847.953996:16168149051:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002970 with delay 10\n[17778:17778:0319/035847.954033:16168149087:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002970\n[17778:17778:0319/035847.954062:16168149115:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[17778:17778:0319/035847.954105:16168149158:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628921960 with a delay 60000, Now = 10000\n[17778:17778:0319/035847.954143:16168149205:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002990 with delay 60\n[17778:17778:0319/035847.954188:16168149241:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000002990\n[17778:17778:0319/035847.954211:16168149266:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[17778:17778:0319/035847.954240:16168149292:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628921960 with a delay 60000, Now = 70000\n[17778:17778:0319/035847.954267:16168149319:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000029b0 with delay 60\n[17778:17778:0319/035847.954292:16168149345:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000029b0\n[17778:17778:0319/035847.954336:16168149388:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[17778:17778:0319/035847.954364:16168149420:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628921960 with a delay 60000, Now = 130000\n[17778:17778:0319/035847.954394:16168149446:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000029d0 with delay 60\n[17778:17778:0319/035847.954421:16168149473:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000029d0\n[17778:17778:0319/035847.954441:16168149494:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[17778:17778:0319/035847.954480:16168149536:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628921960 with a delay 60000, Now = 190000\n[17778:17778:0319/035847.954507:16168149559:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x6020000029f0 with delay 60\n[17778:17778:0319/035847.954532:16168149592:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x6020000029f0\n[17778:17778:0319/035847.954570:16168149624:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[17778:17778:0319/035847.954596:16168149649:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628921960 with a delay 60000, Now = 250000\n[17778:17778:0319/035847.954631:16168149683:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000002a10 with delay 60\n[17778:17778:0319/035847.954657:16168149709:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000002a10\n[17778:17778:0319/035847.954678:16168149731:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[17778:17778:0319/035847.954700:16168149757:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628921960 with a delay 60000, Now = 310000\n[17778:17778:0319/035847.954728:16168149780:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000002a30 with delay 60\n[17778:17778:0319/035847.954753:16168149805:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000002a30\n[17778:17778:0319/035847.954779:16168149831:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[17778:17778:0319/035847.954799:16168149855:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628921960 with a delay 60000, Now = 370000\n[17778:17778:0319/035847.954830:16168149882:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000002a50 with delay 60\n[17778:17778:0319/035847.954855:16168149916:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000002a50\n[17778:17778:0319/035847.954889:16168149941:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (2 ms)\n[4/28] RecurringTaskTest.PeriodicTask (2 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[17778:17778:0319/035847.955997:16168151050:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1628777576 with a delay 10000, Now = 0\n[17778:17778:0319/035847.956039:16168151096:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002ad0 with delay 10\n[17778:17778:0319/035847.956070:16168151121:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002ad0\n[17778:17778:0319/035847.956098:16168151150:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[17778:17778:0319/035847.956135:16168151189:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628777576 with a delay 50000, Now = 10000\n[17778:17778:0319/035847.956175:16168151228:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002af0 with delay 50\n[17778:17778:0319/035847.956228:16168151283:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000002af0\n[17778:17778:0319/035847.956252:16168151304:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[17778:17778:0319/035847.956276:16168151328:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628777576 with a delay 149000, Now = 60000\n[17778:17778:0319/035847.956298:16168151363:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000002b10 with delay 149\n[17778:17778:0319/035847.956346:16168151399:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000002b10\n[17778:17778:0319/035847.956376:16168151429:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[17778:17778:0319/035847.956401:16168151453:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628777576 with a delay 248000, Now = 210000\n[17778:17778:0319/035847.956426:16168151478:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000002b30 with delay 248\n[17778:17778:0319/035847.956460:16168151513:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000002b30\n[17778:17778:0319/035847.956484:16168151539:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[17778:17778:0319/035847.956524:16168151578:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628777576 with a delay 446000, Now = 460000\n[17778:17778:0319/035847.956560:16168151613:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000002b50 with delay 446\n[17778:17778:0319/035847.956610:16168151663:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000002b50\n[17778:17778:0319/035847.956633:16168151685:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[17778:17778:0319/035847.956657:16168151712:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628777576 with a delay 842000, Now = 910000\n[17778:17778:0319/035847.956701:16168151757:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000002b70 with delay 842\n[17778:17778:0319/035847.956753:16168151805:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000002b70\n[17778:17778:0319/035847.956781:16168151833:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[17778:17778:0319/035847.956803:16168151855:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628777576 with a delay 1040000, Now = 1760000\n[17778:17778:0319/035847.956827:16168151880:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000002b90 with delay 1040\n[17778:17778:0319/035847.956883:16168151936:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000002b90\n[17778:17778:0319/035847.956926:16168151982:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[17778:17778:0319/035847.956975:16168152027:INFO:recurring-task.cc(55)] [Retry] Scheduling 1628777576 with a delay 1040000, Now = 2800000\n[17778:17778:0319/035847.957000:16168152053:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000002bb0 with delay 1040\n[17778:17778:0319/035847.957049:16168152101:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000002bb0\n[17778:17778:0319/035847.957071:16168152123: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[17778:17778:0319/035847.958044:16168153097:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1628766312 with a delay 10000, Now = 0\n[17778:17778:0319/035847.958091:16168153145:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002c30 with delay 10\n[17778:17778:0319/035847.958127:16168153183:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002c30\n[17778:17778:0319/035847.958157:16168153209:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[17778:17778:0319/035847.958187:16168153240:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1628766312 with a delay 10000, Now = 10000\n[17778:17778:0319/035847.958226:16168153285:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002c50 with delay 10\n[17778:17778:0319/035847.958260:16168153315:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000002c50\n[17778:17778:0319/035847.958288:16168153341: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[17778:17778:0319/035847.959391:16168154446:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000002cd0 with delay 920\n[17778:17778:0319/035847.959451:16168154503:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002cd0\n[17778:17778:0319/035847.959746:16168154806:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002cf0 with delay 45000\n[17778:17778:0319/035847.960615:16168155671:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002cf0\n[ OK ] ThrottleTest.ThrottlingScripted (1 ms)\n[7/28] ThrottleTest.ThrottlingScripted (1 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[17778:17778:0319/035847.960742:16168155796:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002d70 with delay 990\n[17778:17778:0319/035847.960807:16168155860:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002d70\n[17778:17778:0319/035847.960849:16168155903:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x602000002d90 with delay 1000\n[17778:17778:0319/035847.960913:16168155969:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x602000002d90\n[17778:17778:0319/035847.960942:16168155994:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x602000002db0 with delay 1000\n[17778:17778:0319/035847.961018:16168156071:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x602000002db0\n[17778:17778:0319/035847.961047:16168156100:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x602000002dd0 with delay 1000\n[17778:17778:0319/035847.961102:16168156155:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x602000002dd0\n[17778:17778:0319/035847.961128:16168156181:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002df0 with delay 1000\n[17778:17778:0319/035847.961222:16168156276:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002df0\n[17778:17778:0319/035847.961252:16168156306:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002e10 with delay 1000\n[17778:17778:0319/035847.961317:16168156370:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002e10\n[17778:17778:0319/035847.961353:16168156411:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002e30 with delay 54000\n[17778:17778:0319/035847.963088:16168158142:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002e30\n[17778:17778:0319/035847.963117:16168158169:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002e50 with delay 1000\n[17778:17778:0319/035847.963186:16168158239:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002e50\n[17778:17778:0319/035847.963211:16168158264:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002e70 with delay 1000\n[17778:17778:0319/035847.963272:16168158325:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002e70\n[17778:17778:0319/035847.963328:16168158383:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000002e90 with delay 1000\n[17778:17778:0319/035847.963395:16168158464:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000002e90\n[17778:17778:0319/035847.963455:16168158514:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000002eb0 with delay 1000\n[17778:17778:0319/035847.963518:16168158571:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000002eb0\n[17778:17778:0319/035847.963551:16168158604:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000002ed0 with delay 1000\n[17778:17778:0319/035847.963607:16168158660:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000002ed0\n[17778:17778:0319/035847.963637:16168158689:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002ef0 with delay 1000\n[17778:17778:0319/035847.963719:16168158772:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002ef0\n[17778:17778:0319/035847.963745:16168158801:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002f10 with delay 54000\n[17778:17778:0319/035847.965515:16168160568:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002f10\n[17778:17778:0319/035847.965544:16168160596:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002f30 with delay 1000\n[17778:17778:0319/035847.965601:16168160654:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002f30\n[17778:17778:0319/035847.965638:16168160692:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002f50 with delay 1000\n[17778:17778:0319/035847.965701:16168160754:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002f50\n[17778:17778:0319/035847.965727:16168160786:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002f70 with delay 1000\n[17778:17778:0319/035847.965791:16168160843:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002f70\n[17778:17778:0319/035847.965831:16168160883:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000002f90 with delay 1000\n[17778:17778:0319/035847.965889:16168160941:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000002f90\n[17778:17778:0319/035847.965914:16168160966:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000002fb0 with delay 1000\n[17778:17778:0319/035847.965973:16168161026:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000002fb0\n[17778:17778:0319/035847.966001:16168161053:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000002fd0 with delay 1000\n[17778:17778:0319/035847.966057:16168161110:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000002fd0\n[17778:17778:0319/035847.966081:16168161133:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002ff0 with delay 54000\n[17778:17778:0319/035847.967838:16168162892:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002ff0\n[17778:17778:0319/035847.967879:16168162933:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000003010 with delay 1000\n[17778:17778:0319/035847.967941:16168162993:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000003010\n[17778:17778:0319/035847.967974:16168163027:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000003030 with delay 1000\n[17778:17778:0319/035847.968032:16168163085:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000003030\n[17778:17778:0319/035847.968060:16168163112:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000003050 with delay 1000\n[17778:17778:0319/035847.968115:16168163167:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000003050\n[17778:17778:0319/035847.968138:16168163192:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000003070 with delay 1000\n[17778:17778:0319/035847.968199:16168163252:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000003070\n[17778:17778:0319/035847.968253:16168163306:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000003090 with delay 1000\n[17778:17778:0319/035847.968318:16168163371:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000003090\n[17778:17778:0319/035847.968344:16168163396:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000030b0 with delay 1000\n[17778:17778:0319/035847.968405:16168163459:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000030b0\n[17778:17778:0319/035847.968434:16168163486:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000030d0 with delay 54000\n[17778:17778:0319/035847.970166:16168165224:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000030d0\n[17778:17778:0319/035847.970202:16168165254:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x6020000030f0 with delay 1000\n[17778:17778:0319/035847.970274:16168165328:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x6020000030f0\n[17778:17778:0319/035847.970313:16168165367:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000003110 with delay 1000\n[17778:17778:0319/035847.970376:16168165429:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000003110\n[17778:17778:0319/035847.970402:16168165454:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000003130 with delay 1000\n[17778:17778:0319/035847.970458:16168165511:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000003130\n[17778:17778:0319/035847.970483:16168165545:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000003150 with delay 1000\n[17778:17778:0319/035847.970558:16168165612:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000003150\n[17778:17778:0319/035847.970587:16168165640:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000003170 with delay 1000\n[17778:17778:0319/035847.970645:16168165698:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000003170\n[17778:17778:0319/035847.970693:16168165747:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000003190 with delay 1000\n[17778:17778:0319/035847.970750:16168165803:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000003190\n[17778:17778:0319/035847.970775:16168165828:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000031b0 with delay 54000\n[17778:17778:0319/035847.972513:16168167565:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000031b0\n[ OK ] ThrottleTest.ThrottlingStorm (12 ms)\n[8/28] ThrottleTest.ThrottlingStorm (12 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[17779:17779:0319/035847.956109:16168151167:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0\n[17779:17779:0319/035847.956368:16168151423:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0\n[17779:17779:0319/035847.956610:16168151667: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[17779:17779:0319/035847.956667:16168151723:INFO:recurring-task.cc(55)] [Startup] Scheduling 24104 with a delay 500000, Now = 210919424\n[17779:17779:0319/035847.956707:16168151761:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 500\n[17779:17779:0319/035847.956775:16168151829:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001e90\n[17779:17779:0319/035847.957027:16168152083: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[17779:17779:0319/035847.957966:16168153023: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[17779:17779:0319/035847.958422:16168153481:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ad0 with delay 0\n[17779:17779:0319/035847.958487:16168153541:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002af0 with delay 0\n[17779:17779:0319/035847.958527:16168153580:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b10 with delay 0\n[17779:17779:0319/035847.958574:16168153630:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b30 with delay 0\n[17779:17779:0319/035847.958622:16168153677:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b50 with delay 0\n[17779:17779:0319/035847.958701:16168153757:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b70 with delay 0\n[17779:17779:0319/035847.958955:16168154012:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002ad0\n[17779:17779:0319/035847.959070:16168154125: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[17779:17779:0319/035847.959131:16168154191:INFO:recurring-task.cc(55)] [Send-info] Scheduling 35624 with a delay 500000, Now = 210919424\n[17779:17779:0319/035847.959182:16168154235:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002d10 with delay 500\n[17779:17779:0319/035847.959217:16168154273:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002af0\n[17779:17779:0319/035847.959264:16168154320:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b10\n[17779:17779:0319/035847.959299:16168154369:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b30\n[17779:17779:0319/035847.959358:16168154413:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b50\n[17779:17779:0319/035847.959395:16168154449:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b70\n[17779:17779:0319/035847.959460:16168154516:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[17779:17779:0319/035847.959542:16168154596:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002d10\n[17779:17779:0319/035847.959698:16168154754:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[17779:17779:0319/035847.960094:16168155150:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } registration_message: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } registration: { object_id: { source: 2 name: \"oid1\" } op_type: UNREGISTER } registration: { object_id: { source: 2 name: \"oid2\" } op_type: UNREGISTER } } registration_sync_message: { subtree: { registered_object: { source: 2 name: \"oid0\" } } } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"unit-test\" } performance_counter: { name: \"x\" value: 3 } performance_counter: { name: \"y\" value: 81 } server_registration_summary_requested: true } }\n[ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (2 ms)\n[11/28] ProtocolHandlerTest.SendMultipleMessageTypes (2 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[17779:17779:0319/035847.961718:16168156776: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 (0 ms)\n[12/28] ProtocolHandlerTest.IncomingCompositeMessage (0 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[17779:17779:0319/035847.962318:16168157375: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[17779:17779:0319/035847.962405:16168157462: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[17779:17779:0319/035847.962515:16168157570: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[17779:17779:0319/035847.962617:16168157673: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 (0 ms)\n[13/28] ProtocolHandlerTest.InvalidInboundMessage (0 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[17779:17779:0319/035847.963129:16168158187: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[17779:17779:0319/035847.963286:16168158343: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[17779:17779:0319/035847.963787:16168158843: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[17779:17779:0319/035847.964285:16168159342: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[17779:17779:0319/035847.964363:16168159419:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004850 with delay 0\n[17779:17779:0319/035847.964404:16168159459:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004850\n[17779:17779:0319/035847.964471:16168159526: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[17779:17779:0319/035847.964515:16168159570:INFO:recurring-task.cc(55)] [Send-info] Scheduling 66728 with a delay 500000, Now = 210919424\n[17779:17779:0319/035847.964550:16168159605:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004870 with delay 500\n[17779:17779:0319/035847.964623:16168159679:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004870\n[17779:17779:0319/035847.964666:16168159722:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (38 ms)\n[16/28] ProtocolHandlerTest.ConfigMessage (38 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[17779:17779:0319/035848.001695:16168196755: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[17779:17779:0319/035848.002198:16168197254: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[17775:17775:0319/035847.948432:16168143490:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 0\n[17775:17775:0319/035847.948731:16168143798:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.949015:16168144072:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002550 with delay 0\n[17775:17775:0319/035847.949061:16168144116:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002030\n[17775:17775:0319/035847.949092:16168144152:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002550\n[17775:17775:0319/035847.949170:16168144229:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.949241:16168144296:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0\n[17775:17775:0319/035847.949318:16168144373:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002610\n[17775:17775:0319/035847.949352:16168144407:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.949386:16168144440:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002650 with delay 0\n[17775:17775:0319/035847.949417:16168144473:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002650\n[17775:17775:0319/035847.949447:16168144503:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.949487:16168144540:INFO:recurring-task.cc(55)] [Startup] Scheduling 24360 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.949526:16168144581:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002670 with delay 0\n[17775:17775:0319/035847.949560:16168144614:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002670\n[17775:17775:0319/035847.949632:16168144686:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3170497865543204686\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.949683:16168144740:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 24616 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.949723:16168144776:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002690 with delay 500\n[17775:17775:0319/035847.949751:16168144808:INFO:recurring-task.cc(55)] [Retry] Scheduling 24360 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.949786:16168144839:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000026b0 with delay 60000\n[17775:17775:0319/035847.949861:16168144916:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002690\n[17775:17775:0319/035847.949891:16168144948:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.949968:16168145027:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.950120:16168145175: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: \"3170497865543204686\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.950260:16168145316:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002750 with delay 0\n[17775:17775:0319/035847.950312:16168145373:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002750\n[17775:17775:0319/035847.950451:16168145509:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3170497865543204686\" 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[17775:17775:0319/035847.950517:16168145573:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3170497865543204686\"\n[17775:17775:0319/035847.950555:16168145609:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.950588:16168145642:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13448 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.950628:16168145682:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002770 with delay 1200000\n[17775:17775:0319/035847.950686:16168145749:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.950854:16168145911:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.950908:16168145964:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 9672 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.950945:16168145999:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002990 with delay 0\n[17775:17775:0319/035847.950999:16168146054: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[17775:17775:0319/035847.951040:16168146095:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002990\n[17775:17775:0319/035847.951121:16168146176:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a50 with delay 0\n[17775:17775:0319/035847.951182:16168146237:INFO:recurring-task.cc(55)] [Retry] Scheduling 9672 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.951217:16168146274:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a90 with delay 10000\n[17775:17775:0319/035847.951252:16168146306:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002a50\n[17775:17775:0319/035847.951291:16168146347:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (4 ms)\n[19/28] InvalidationClientImplTest.Start (4 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[17775:17775:0319/035847.951951:16168147008:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000032f0 with delay 0\n[17775:17775:0319/035847.952012:16168147066: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[17775:17775:0319/035847.952523:16168147584:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 0\n[17775:17775:0319/035847.952599:16168147663:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.952875:16168147933:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000041f0 with delay 0\n[17775:17775:0319/035847.952926:16168147979:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b90\n[17775:17775:0319/035847.952979:16168148036:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000041f0\n[17775:17775:0319/035847.953045:16168148102:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.953104:16168148160:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042b0 with delay 0\n[17775:17775:0319/035847.953141:16168148196:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042b0\n[17775:17775:0319/035847.953184:16168148239:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.953229:16168148285:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042f0 with delay 0\n[17775:17775:0319/035847.953274:16168148328:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042f0\n[17775:17775:0319/035847.953312:16168148367:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.953365:16168148420:INFO:recurring-task.cc(55)] [Startup] Scheduling 48296 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.953402:16168148456:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004310 with delay 0\n[17775:17775:0319/035847.953435:16168148488:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004310\n[17775:17775:0319/035847.953498:16168148552:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2017791512857049267\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.953547:16168148603:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 48552 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.953583:16168148640:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004330 with delay 500\n[17775:17775:0319/035847.953620:16168148673:INFO:recurring-task.cc(55)] [Retry] Scheduling 48296 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.953648:16168148710:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004350 with delay 60000\n[17775:17775:0319/035847.953749:16168148805:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004330\n[17775:17775:0319/035847.953783:16168148852:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.953854:16168148910:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.954006:16168149063: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: \"-2017791512857049267\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.954113:16168149169:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000043f0 with delay 0\n[17775:17775:0319/035847.954161:16168149219:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000043f0\n[17775:17775:0319/035847.954285:16168149341:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2017791512857049267\" 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[17775:17775:0319/035847.954370:16168149426:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2017791512857049267\"\n[17775:17775:0319/035847.954407:16168149461:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.954443:16168149502:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15736 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.954482:16168149537:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004410 with delay 1200000\n[17775:17775:0319/035847.954518:16168149571:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.954661:16168149717:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.954710:16168149764:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 14088 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.954757:16168149813:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004630 with delay 0\n[17775:17775:0319/035847.954809:16168149866: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[17775:17775:0319/035847.954866:16168149921:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004630\n[17775:17775:0319/035847.954940:16168149996:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000046f0 with delay 0\n[17775:17775:0319/035847.954981:16168150034:INFO:recurring-task.cc(55)] [Retry] Scheduling 14088 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.955012:16168150067:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004730 with delay 10000\n[17775:17775:0319/035847.955043:16168150097:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000046f0\n[17775:17775:0319/035847.955071:16168150134:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.955156:16168150214:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004750 with delay 0\n[17775:17775:0319/035847.955190:16168150243:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000004750\n[17775:17775:0319/035847.955263:16168150319:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[17775:17775:0319/035847.955315:16168150372:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[17775:17775:0319/035847.955358:16168150414:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[17775:17775:0319/035847.955440:16168150496:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 48552 with a delay 500000, Now = 211469424\n[17775:17775:0319/035847.955478:16168150532:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004770 with delay 500\n[17775:17775:0319/035847.955524:16168150580:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 48424 with a delay 60000000, Now = 211469424\n[17775:17775:0319/035847.955559:16168150615:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004790 with delay 60000\n[17775:17775:0319/035847.955640:16168150695:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004770\n[17775:17775:0319/035847.955686:16168150739:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.955728:16168150782:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.955758:16168150812:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[17775:17775:0319/035847.955921:16168150976: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[17775:17775:0319/035847.956014:16168151072:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.956103:16168151159:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000004830 with delay 0\n[17775:17775:0319/035847.956142:16168151196:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004830\n[17775:17775:0319/035847.956370:16168151426: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[17775:17775:0319/035847.956470:16168151525: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[17775:17775:0319/035847.956545:16168151601:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[17775:17775:0319/035847.956652:16168151713:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[17775:17775:0319/035847.956761:16168151816:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[17775:17775:0319/035847.957174:16168152229:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000004730\n[ OK ] InvalidationClientImplTest.Register (6 ms)\n[21/28] InvalidationClientImplTest.Register (6 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[17775:17775:0319/035847.958719:16168153776:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005410 with delay 0\n[17775:17775:0319/035847.958781:16168153834:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.959077:16168154133:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005af0 with delay 0\n[17775:17775:0319/035847.959117:16168154189:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005410\n[17775:17775:0319/035847.959176:16168154232:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005af0\n[17775:17775:0319/035847.959236:16168154290:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.959291:16168154346:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bb0 with delay 0\n[17775:17775:0319/035847.959343:16168154396:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bb0\n[17775:17775:0319/035847.959367:16168154420:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.959404:16168154457:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bf0 with delay 0\n[17775:17775:0319/035847.959435:16168154488:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bf0\n[17775:17775:0319/035847.959461:16168154514:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.959494:16168154548:INFO:recurring-task.cc(55)] [Startup] Scheduling 79400 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.959524:16168154578:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c10 with delay 0\n[17775:17775:0319/035847.959555:16168154607:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005c10\n[17775:17775:0319/035847.959633:16168154687:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4991301800772152636\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.959682:16168154736:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 79656 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.959717:16168154773:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c30 with delay 500\n[17775:17775:0319/035847.959749:16168154802:INFO:recurring-task.cc(55)] [Retry] Scheduling 79400 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.959780:16168154833:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c50 with delay 60000\n[17775:17775:0319/035847.959823:16168154877:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005c30\n[17775:17775:0319/035847.959851:16168154904:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.959896:16168154951:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.960008:16168155062: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: \"-4991301800772152636\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.960101:16168155155:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005cf0 with delay 0\n[17775:17775:0319/035847.960132:16168155187:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005cf0\n[17775:17775:0319/035847.960269:16168155325:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4991301800772152636\" 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[17775:17775:0319/035847.960337:16168155392:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4991301800772152636\"\n[17775:17775:0319/035847.960369:16168155423:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.960404:16168155458:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20840 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.960436:16168155490:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005d10 with delay 1200000\n[17775:17775:0319/035847.960468:16168155522:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.960596:16168155651:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.960635:16168155689:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 20808 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.960675:16168155728:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005f30 with delay 0\n[17775:17775:0319/035847.960734:16168155789: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[17775:17775:0319/035847.960798:16168155854:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005f30\n[17775:17775:0319/035847.960865:16168155920:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005ff0 with delay 0\n[17775:17775:0319/035847.960919:16168155975:INFO:recurring-task.cc(55)] [Retry] Scheduling 20808 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.960979:16168156038:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006030 with delay 10000\n[17775:17775:0319/035847.961017:16168156070:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005ff0\n[17775:17775:0319/035847.961044:16168156098:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.961090:16168156145:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.961143:16168156198:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006050 with delay 0\n[17775:17775:0319/035847.961178:16168156232:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006050\n[17775:17775:0319/035847.961398:16168156455: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[17775:17775:0319/035847.961484:16168156539: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[17775:17775:0319/035847.961583:16168156639: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[17775:17775:0319/035847.961701:16168156756: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[17775:17775:0319/035847.961786:16168156841: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[17775:17775:0319/035847.961868:16168156924:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006430 with delay 0\n[17775:17775:0319/035847.961904:16168156958:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006450 with delay 0\n[17775:17775:0319/035847.961934:16168156988:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006470 with delay 0\n[17775:17775:0319/035847.961966:16168157022:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006430\n[17775:17775:0319/035847.962032:16168157089:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 79656 with a delay 500000, Now = 211519424\n[17775:17775:0319/035847.962072:16168157126:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006490 with delay 500\n[17775:17775:0319/035847.962119:16168157176:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006450\n[17775:17775:0319/035847.962158:16168157214:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006470\n[17775:17775:0319/035847.962226:16168157281:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x602000006490\n[17775:17775:0319/035847.962262:16168157316:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.962323:16168157387:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.962373:16168157429:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[17775:17775:0319/035847.962549:16168157604:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: \"2\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } }\n[ OK ] InvalidationClientImplTest.Invalidations (4 ms)\n[22/28] InvalidationClientImplTest.Invalidations (4 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[17775:17775:0319/035847.963258:16168158315:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006d70 with delay 0\n[17775:17775:0319/035847.963345:16168158401:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.963582:16168158639:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0\n[17775:17775:0319/035847.963620:16168158676:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006d70\n[17775:17775:0319/035847.963652:16168158715:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290\n[17775:17775:0319/035847.963738:16168158794:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.963800:16168158856:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007350 with delay 0\n[17775:17775:0319/035847.963839:16168158893:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007350\n[17775:17775:0319/035847.963870:16168158925:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.963903:16168158957:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007390 with delay 0\n[17775:17775:0319/035847.963932:16168158985:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007390\n[17775:17775:0319/035847.963958:16168159012:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.964010:16168159069:INFO:recurring-task.cc(55)] [Startup] Scheduling 109096 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.964052:16168159108:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073b0 with delay 0\n[17775:17775:0319/035847.964083:16168159136:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000073b0\n[17775:17775:0319/035847.964145:16168159201:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8564041444079378553\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.964192:16168159246:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 109352 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.964224:16168159281:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073d0 with delay 500\n[17775:17775:0319/035847.964257:16168159319:INFO:recurring-task.cc(55)] [Retry] Scheduling 109096 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.964321:16168159377:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073f0 with delay 60000\n[17775:17775:0319/035847.964406:16168159463:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000073d0\n[17775:17775:0319/035847.964444:16168159497:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.964485:16168159541:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.964603:16168159659: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: \"8564041444079378553\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.964714:16168159769:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007490 with delay 0\n[17775:17775:0319/035847.964764:16168159820:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007490\n[17775:17775:0319/035847.964877:16168159931:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8564041444079378553\" 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[17775:17775:0319/035847.964929:16168159985:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8564041444079378553\"\n[17775:17775:0319/035847.964984:16168160039:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.965039:16168160096:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 24888 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.965075:16168160130:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000074b0 with delay 1200000\n[17775:17775:0319/035847.965111:16168160166:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.965235:16168160290:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.965291:16168160347:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 26952 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.965336:16168160393:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076d0 with delay 0\n[17775:17775:0319/035847.965395:16168160450: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[17775:17775:0319/035847.965436:16168160490:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000076d0\n[17775:17775:0319/035847.965500:16168160556:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007790 with delay 0\n[17775:17775:0319/035847.965540:16168160603:INFO:recurring-task.cc(55)] [Retry] Scheduling 26952 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.965595:16168160650:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000077d0 with delay 10000\n[17775:17775:0319/035847.965631:16168160686:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007790\n[17775:17775:0319/035847.965666:16168160719:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.965729:16168160786:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.965780:16168160835:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000077f0 with delay 0\n[17775:17775:0319/035847.965814:16168160868:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000077f0\n[17775:17775:0319/035847.965939:16168160995: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[17775:17775:0319/035847.966017:16168161074: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[17775:17775:0319/035847.966063:16168161117:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[17775:17775:0319/035847.966101:16168161155:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 109352 with a delay 500000, Now = 211469424\n[17775:17775:0319/035847.966135:16168161189:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007810 with delay 500\n[17775:17775:0319/035847.966173:16168161227:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[17775:17775:0319/035847.966397:16168161454: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[17775:17775:0319/035847.966499:16168161555:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007810\n[17775:17775:0319/035847.966533:16168161587:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.966615:16168161672:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.966660:16168161715:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[17775:17775:0319/035847.966996:16168162052: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[17775:17775:0319/035847.967437:16168162494:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000077d0\n[ OK ] InvalidationClientImplTest.ServerRequests (6 ms)\n[23/28] InvalidationClientImplTest.ServerRequests (6 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[17775:17775:0319/035847.968865:16168163921:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000080f0 with delay 0\n[17775:17775:0319/035847.968922:16168163977:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.969195:16168164251:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000086b0 with delay 0\n[17775:17775:0319/035847.969237:16168164291:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000080f0\n[17775:17775:0319/035847.969265:16168164319:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000086b0\n[17775:17775:0319/035847.969337:16168164390:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.969389:16168164444:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008770 with delay 0\n[17775:17775:0319/035847.969441:16168164495:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008770\n[17775:17775:0319/035847.969468:16168164522:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.969508:16168164562:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0\n[17775:17775:0319/035847.969540:16168164595:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0\n[17775:17775:0319/035847.969567:16168164621:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.969598:16168164652:INFO:recurring-task.cc(55)] [Startup] Scheduling 136360 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.969634:16168164689:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087d0 with delay 0\n[17775:17775:0319/035847.969670:16168164724:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087d0\n[17775:17775:0319/035847.969727:16168164782:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-8760662084039904187\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.969763:16168164817:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 136616 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.969811:16168164866:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087f0 with delay 500\n[17775:17775:0319/035847.969840:16168164896:INFO:recurring-task.cc(55)] [Retry] Scheduling 136360 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.969870:16168164924:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008810 with delay 60000\n[17775:17775:0319/035847.969912:16168164966:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000087f0\n[17775:17775:0319/035847.969941:16168164994:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.969998:16168165054:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.970127:16168165185: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: \"-8760662084039904187\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.970236:16168165293:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088b0 with delay 0\n[17775:17775:0319/035847.970272:16168165326:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000088b0\n[17775:17775:0319/035847.970401:16168165457:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-8760662084039904187\" 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[17775:17775:0319/035847.970464:16168165519:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-8760662084039904187\"\n[17775:17775:0319/035847.970511:16168165566:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.970549:16168165604:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28408 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.970585:16168165639:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088d0 with delay 1200000\n[17775:17775:0319/035847.970631:16168165688:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.970758:16168165815:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.970796:16168165850:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 32328 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.970828:16168165882:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008af0 with delay 0\n[17775:17775:0319/035847.970873:16168165927: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[17775:17775:0319/035847.970914:16168165968:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008af0\n[17775:17775:0319/035847.971004:16168166060:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bb0 with delay 0\n[17775:17775:0319/035847.971047:16168166100:INFO:recurring-task.cc(55)] [Retry] Scheduling 32328 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.971076:16168166130:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bf0 with delay 10000\n[17775:17775:0319/035847.971109:16168166162:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008bb0\n[17775:17775:0319/035847.971134:16168166188:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.971179:16168166235:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.971229:16168166283:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000008c10 with delay 0\n[17775:17775:0319/035847.971275:16168166330:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000008c10\n[17775:17775:0319/035847.971393:16168166449: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[17775:17775:0319/035847.971464:16168166518: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[17775:17775:0319/035847.971501:16168166555:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[17775:17775:0319/035847.971841:16168166898:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000008bf0\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms)\n[24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[17775:17775:0319/035847.973181:16168168236:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009570 with delay 0\n[17775:17775:0319/035847.973249:16168168303:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.973520:16168168576:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009bf0 with delay 0\n[17775:17775:0319/035847.973559:16168168612:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009570\n[17775:17775:0319/035847.973591:16168168644:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009bf0\n[17775:17775:0319/035847.973647:16168168710:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.973722:16168168778:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cb0 with delay 0\n[17775:17775:0319/035847.973766:16168168819:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cb0\n[17775:17775:0319/035847.973804:16168168858:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.973849:16168168904:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cf0 with delay 0\n[17775:17775:0319/035847.973880:16168168933:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cf0\n[17775:17775:0319/035847.973904:16168168959:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.973938:16168168992:INFO:recurring-task.cc(55)] [Startup] Scheduling 159016 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.973969:16168169024:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d10 with delay 0\n[17775:17775:0319/035847.973998:16168169051:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009d10\n[17775:17775:0319/035847.974089:16168169144:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"817847240265526366\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.974130:16168169184:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 159272 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.974164:16168169218:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d30 with delay 500\n[17775:17775:0319/035847.974192:16168169246:INFO:recurring-task.cc(55)] [Retry] Scheduling 159016 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.974222:16168169276:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d50 with delay 60000\n[17775:17775:0319/035847.974273:16168169327:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009d30\n[17775:17775:0319/035847.974319:16168169374:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.974361:16168169415:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.974520:16168169576: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: \"817847240265526366\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.974629:16168169684:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009df0 with delay 0\n[17775:17775:0319/035847.974677:16168169731:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009df0\n[17775:17775:0319/035847.974820:16168169875:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"817847240265526366\" 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[17775:17775:0319/035847.974876:16168169931:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"817847240265526366\"\n[17775:17775:0319/035847.974914:16168169968:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.974949:16168170002:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31576 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.974979:16168170032:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009e10 with delay 1200000\n[17775:17775:0319/035847.975008:16168170062:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.975158:16168170213:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.975201:16168170256:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 35976 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.975234:16168170288:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a030 with delay 0\n[17775:17775:0319/035847.975281:16168170335: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[17775:17775:0319/035847.975330:16168170384:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a030\n[17775:17775:0319/035847.975391:16168170448:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a0f0 with delay 0\n[17775:17775:0319/035847.975432:16168170486:INFO:recurring-task.cc(55)] [Retry] Scheduling 35976 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.975462:16168170516:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a130 with delay 10000\n[17775:17775:0319/035847.975504:16168170559:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a0f0\n[17775:17775:0319/035847.975536:16168170589:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.975599:16168170654:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a150 with delay 0\n[17775:17775:0319/035847.975630:16168170683:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000a150\n[17775:17775:0319/035847.975675:16168170731:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[17775:17775:0319/035847.975744:16168170799:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 159272 with a delay 500000, Now = 211469424\n[17775:17775:0319/035847.975776:16168170830:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a170 with delay 500\n[17775:17775:0319/035847.975815:16168170869:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 159144 with a delay 60000000, Now = 211469424\n[17775:17775:0319/035847.975846:16168170900:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a190 with delay 60000\n[17775:17775:0319/035847.975903:16168170958:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a170\n[17775:17775:0319/035847.975931:16168170984:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.975978:16168171032:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.976006:16168171060:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[17775:17775:0319/035847.976119:16168171174: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[17775:17775:0319/035847.976218:16168171281:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.976280:16168171336:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000a230 with delay 0\n[17775:17775:0319/035847.976323:16168171378:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a230\n[17775:17775:0319/035847.976439:16168171494: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[17775:17775:0319/035847.976525:16168171580: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[17775:17775:0319/035847.976558:16168171613:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[17775:17775:0319/035847.976666:16168171722:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[17775:17775:0319/035847.977071:16168172126:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000a130\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms)\n[25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[17775:17775:0319/035847.978472:16168173528:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ac90 with delay 0\n[17775:17775:0319/035847.978541:16168173596:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.978789:16168173844:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b1b0 with delay 0\n[17775:17775:0319/035847.978829:16168173882:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ac90\n[17775:17775:0319/035847.978855:16168173909:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b1b0\n[17775:17775:0319/035847.978910:16168173965:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.978963:16168174018:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b270 with delay 0\n[17775:17775:0319/035847.978999:16168174052:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b270\n[17775:17775:0319/035847.979031:16168174085:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.979079:16168174135:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2b0 with delay 0\n[17775:17775:0319/035847.979120:16168174176:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2b0\n[17775:17775:0319/035847.979151:16168174209:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.979188:16168174242:INFO:recurring-task.cc(55)] [Startup] Scheduling 187432 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.979225:16168174278:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2d0 with delay 0\n[17775:17775:0319/035847.979252:16168174305:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2d0\n[17775:17775:0319/035847.979317:16168174371:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2011462497433576127\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.979356:16168174410:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 187688 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.979387:16168174440:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2f0 with delay 500\n[17775:17775:0319/035847.979413:16168174467:INFO:recurring-task.cc(55)] [Retry] Scheduling 187432 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.979448:16168174501:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b310 with delay 60000\n[17775:17775:0319/035847.979493:16168174547:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b2f0\n[17775:17775:0319/035847.979521:16168174574:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.979564:16168174618:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.979698:16168174760: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: \"2011462497433576127\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.979835:16168174890:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3b0 with delay 0\n[17775:17775:0319/035847.979873:16168174926:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b3b0\n[17775:17775:0319/035847.979971:16168175024:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2011462497433576127\" 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[17775:17775:0319/035847.980031:16168175087:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2011462497433576127\"\n[17775:17775:0319/035847.980069:16168175123:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.980103:16168175156:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 34920 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.980138:16168175192:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3d0 with delay 1200000\n[17775:17775:0319/035847.980172:16168175226:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.980324:16168175379:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.980375:16168175430:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 41352 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.980408:16168175462:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b5f0 with delay 0\n[17775:17775:0319/035847.980453:16168175507: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[17775:17775:0319/035847.980489:16168175542:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b5f0\n[17775:17775:0319/035847.980549:16168175608:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6b0 with delay 0\n[17775:17775:0319/035847.980592:16168175646:INFO:recurring-task.cc(55)] [Retry] Scheduling 41352 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.980622:16168175676:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6f0 with delay 10000\n[17775:17775:0319/035847.980651:16168175713:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b6b0\n[17775:17775:0319/035847.980687:16168175741:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.980735:16168175791:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b710 with delay 0\n[17775:17775:0319/035847.980771:16168175825:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000b710\n[17775:17775:0319/035847.980809:16168175864:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[17775:17775:0319/035847.980875:16168175931:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 187688 with a delay 500000, Now = 211469424\n[17775:17775:0319/035847.980921:16168175979:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b730 with delay 500\n[17775:17775:0319/035847.980985:16168176041:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 187560 with a delay 60000000, Now = 211469424\n[17775:17775:0319/035847.981024:16168176078:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b750 with delay 60000\n[17775:17775:0319/035847.981082:16168176137:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000b730\n[17775:17775:0319/035847.981111:16168176173:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.981172:16168176227:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.981203:16168176257:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[17775:17775:0319/035847.981334:16168176390: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[17775:17775:0319/035847.981678:16168176733:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000b6f0\n[17775:17775:0319/035847.982620:16168177675:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000b310\n[17775:17775:0319/035847.982668:16168177722:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000b750\n[17775:17775:0319/035847.982740:16168177795: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[17775:17775:0319/035847.982777:16168177830:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[17775:17775:0319/035847.982847:16168177900: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[17775:17775:0319/035847.982883:16168177936:INFO:recurring-task.cc(55)] [Send-info] Scheduling 187688 with a delay 500000, Now = 271469424\n[17775:17775:0319/035847.982918:16168177971:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b7f0 with delay 500\n[17775:17775:0319/035847.982946:16168177998:INFO:recurring-task.cc(55)] [Retry] Scheduling 187560 with a delay 60000000, Now = 271469424\n[17775:17775:0319/035847.982977:16168178030:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b810 with delay 60000\n[17775:17775:0319/035847.983015:16168178068:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000b7f0\n[17775:17775:0319/035847.983046:16168178100:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.983094:16168178150:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.983125:16168178178:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[17775:17775:0319/035847.983275:16168178330: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 (6 ms)\n[26/28] InvalidationClientImplTest.NetworkTimeouts (6 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[17775:17775:0319/035847.984893:16168179949:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c0f0 with delay 0\n[17775:17775:0319/035847.984951:16168180023:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.985197:16168180253:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c610 with delay 0\n[17775:17775:0319/035847.985241:16168180296:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c0f0\n[17775:17775:0319/035847.985274:16168180328:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c610\n[17775:17775:0319/035847.985340:16168180393:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.985396:16168180452:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6d0 with delay 0\n[17775:17775:0319/035847.985436:16168180489:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6d0\n[17775:17775:0319/035847.985460:16168180513:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.985505:16168180561:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c710 with delay 0\n[17775:17775:0319/035847.985538:16168180591:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c710\n[17775:17775:0319/035847.985563:16168180616:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.985600:16168180654:INFO:recurring-task.cc(55)] [Startup] Scheduling 216360 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.985629:16168180682:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c730 with delay 0\n[17775:17775:0319/035847.985672:16168180727:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c730\n[17775:17775:0319/035847.985747:16168180802:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1924627579948302287\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.985783:16168180839:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 216616 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.985815:16168180868:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c750 with delay 500\n[17775:17775:0319/035847.985873:16168180929:INFO:recurring-task.cc(55)] [Retry] Scheduling 216360 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.985905:16168180963:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c770 with delay 60000\n[17775:17775:0319/035847.985949:16168181002:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c750\n[17775:17775:0319/035847.985979:16168181033:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.986018:16168181071:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.986136:16168181192: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: \"-1924627579948302287\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.986253:16168181308:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c810 with delay 0\n[17775:17775:0319/035847.986286:16168181361:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c810\n[17775:17775:0319/035847.986457:16168181513:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1924627579948302287\" 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[17775:17775:0319/035847.986520:16168181573:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1924627579948302287\"\n[17775:17775:0319/035847.986552:16168181605:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.986584:16168181638:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 37560 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.986618:16168181671:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c830 with delay 1200000\n[17775:17775:0319/035847.986651:16168181711:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.986791:16168181846:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.986832:16168181886:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 47304 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.986863:16168181917:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ca50 with delay 0\n[17775:17775:0319/035847.986909:16168181964: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[17775:17775:0319/035847.986968:16168182024:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ca50\n[17775:17775:0319/035847.987033:16168182087:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb10 with delay 0\n[17775:17775:0319/035847.987075:16168182129:INFO:recurring-task.cc(55)] [Retry] Scheduling 47304 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.987106:16168182159:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb50 with delay 10000\n[17775:17775:0319/035847.987132:16168182189:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cb10\n[17775:17775:0319/035847.987164:16168182217:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.987212:16168182266:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035847.987251:16168182306:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000cb70 with delay 0\n[17775:17775:0319/035847.987281:16168182334:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000cb70\n[17775:17775:0319/035847.987381:16168182435: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[17775:17775:0319/035847.987672:16168182727:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000cb50\n[17775:17775:0319/035847.988503:16168183562: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[17775:17775:0319/035847.989108:16168184164:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0\n[17775:17775:0319/035847.989171:16168184225:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[17775:17775:0319/035847.989372:16168184435:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d8f0 with delay 0\n[17775:17775:0319/035847.989446:16168184503:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0\n[17775:17775:0319/035847.989477:16168184530:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d8f0\n[17775:17775:0319/035847.989531:16168184585:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[17775:17775:0319/035847.989599:16168184655:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9b0 with delay 0\n[17775:17775:0319/035847.989637:16168184691:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9b0\n[17775:17775:0319/035847.989673:16168184726:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[17775:17775:0319/035847.989704:16168184758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9f0 with delay 0\n[17775:17775:0319/035847.989732:16168184785:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9f0\n[17775:17775:0319/035847.989757:16168184810:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[17775:17775:0319/035847.989789:16168184843:INFO:recurring-task.cc(55)] [Startup] Scheduling 237992 with a delay 0, Now = 210919424\n[17775:17775:0319/035847.989823:16168184876:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da10 with delay 0\n[17775:17775:0319/035847.989851:16168184905:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000da10\n[17775:17775:0319/035847.989912:16168184966:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4424994045207206773\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[17775:17775:0319/035847.989947:16168185001:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 238248 with a delay 500000, Now = 210919424\n[17775:17775:0319/035847.989991:16168185050:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da30 with delay 500\n[17775:17775:0319/035847.990024:16168185078:INFO:recurring-task.cc(55)] [Retry] Scheduling 237992 with a delay 60000000, Now = 210919424\n[17775:17775:0319/035847.990056:16168185110:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da50 with delay 60000\n[17775:17775:0319/035847.990096:16168185150:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000da30\n[17775:17775:0319/035847.990127:16168185181:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.990186:16168185241:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[17775:17775:0319/035847.990315:16168185369: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: \"-4424994045207206773\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[17775:17775:0319/035847.990425:16168185480:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000daf0 with delay 0\n[17775:17775:0319/035847.990459:16168185513:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000daf0\n[17775:17775:0319/035847.990586:16168185642:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4424994045207206773\" 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[17775:17775:0319/035847.990639:16168185692:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4424994045207206773\"\n[17775:17775:0319/035847.990680:16168185734:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[17775:17775:0319/035847.990716:16168185771:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 40024 with a delay 1200000000, Now = 211419424\n[17775:17775:0319/035847.990746:16168185799:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000db10 with delay 1200000\n[17775:17775:0319/035847.990779:16168185833:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[17775:17775:0319/035847.990910:16168185965:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035847.990947:16168186001:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 67272 with a delay 0, Now = 211419424\n[17775:17775:0319/035847.990980:16168186034:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000dd30 with delay 0\n[17775:17775:0319/035847.991025:16168186078: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[17775:17775:0319/035847.991061:16168186115:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000dd30\n[17775:17775:0319/035847.991124:16168186179:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ddf0 with delay 0\n[17775:17775:0319/035847.991175:16168186229:INFO:recurring-task.cc(55)] [Retry] Scheduling 67272 with a delay 10000000, Now = 211419424\n[17775:17775:0319/035847.991223:16168186278:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000de30 with delay 10000\n[17775:17775:0319/035847.991256:16168186310:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ddf0\n[17775:17775:0319/035847.991295:16168186360:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[17775:17775:0319/035847.991601:16168186655:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000de30\n[17775:17775:0319/035847.992549:16168187603:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000da50\n[17775:17775:0319/035848.013223:16168208282:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000db10\n[17775:17775:0319/035848.013312:16168208367:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035848.013375:16168208429:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[17775:17775:0319/035848.013421:16168208474:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[17775:17775:0319/035848.013611:16168208668: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[17775:17775:0319/035848.013688:16168208744:INFO:recurring-task.cc(55)] [Send-info] Scheduling 238248 with a delay 500000, Now = 1411419424\n[17775:17775:0319/035848.013729:16168208783:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de50 with delay 500\n[17775:17775:0319/035848.013769:16168208822:INFO:recurring-task.cc(55)] [Retry] Scheduling 40024 with a delay 1200000000, Now = 1411419424\n[17775:17775:0319/035848.013801:16168208854:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de70 with delay 1200000\n[17775:17775:0319/035848.013862:16168208918:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000de50\n[17775:17775:0319/035848.013900:16168208954:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035848.013963:16168209016:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[17775:17775:0319/035848.013994:16168209051:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[17775:17775:0319/035848.014223:16168209277: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 (27 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (27 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "2c9b1166da64d336f776ea23e561080c26569f61", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43ae6c01baea8711", "server_versions": [ "4201-b04f7f8" ], "started_ts": "2019-03-19T10:58:43.383861", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux ASan LSan Tests (1)", "buildnumber:58501", "cpu:x86-64", "data:41e85c64ae1f7e0e12dd83442f4f5d749c1393da", "gpu:none", "master:chromium.memory", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "pool:Chrome", "priority:25", "project:chromium", "purpose:CI", "purpose:luci", "purpose:post-commit", "service_account:none", "slavename:swarm594-c4", "spec_name:chromium.ci:Linux ASan LSan Tests (1)", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:301b8e63a30efe760c5077d38a79f758c770c9ac", "user:None" ], "task_id": "43af06c3d99c0010" } ] }