Back to build
Raw log | Switch to full mode | Login

{ "shards": [ { "bot_dimensions": [ { "key": "caches", "value": [ "swarming_module_cache_vpython" ] }, { "key": "cores", "value": [ "8" ] }, { "key": "cpu", "value": [ "x86", "x86-64", "x86-64-Broadwell_GCE", "x86-64-avx2" ] }, { "key": "gce", "value": [ "1" ] }, { "key": "gpu", "value": [ "none" ] }, { "key": "id", "value": [ "chrome-trusty-82-zk9w" ] }, { "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-east", "us-east1", "us-east1-b" ] } ], "bot_id": "chrome-trusty-82-zk9w", "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-18T20:23:08.632804", "cost_saved_usd": 0.0008312424203753119, "created_ts": "2019-03-19T02:03:09.801009", "deduped_from": "43ab4a4827b6ee11", "duration": 0.8223779201507568, "modified_ts": "2019-03-19T02:03:09.904047", "name": "cacheinvalidation_unittests/Ubuntu-14.04/92bae042ef/Linux ASan LSan Tests (1)/58476", "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/ioh9Ec91/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[19869:19869:0318/132307.425461:46918060277:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0\n[19869:19869:0318/132307.425566:46918060376:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0\n[19869:19869:0318/132307.425909:46918060721: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[19869:19869:0318/132307.425967:46918060775:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24488 with a delay 500000, Now = 210919424\n[19869:19869:0318/132307.426016:46918060830:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d10 with delay 500\n[19869:19869:0318/132307.426092:46918060903:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d10\n[19869:19869:0318/132307.426263:46918061073:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[19869:19869:0318/132307.426291:46918061102:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\n[1/28] ProtocolHandlerTest.TokenMissing (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[19869:19869:0318/132307.426893:46918061708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002290 with delay 0\n[19869:19869:0318/132307.426934:46918061742:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002290\n[19869:19869:0318/132307.426969:46918061778:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 29480 with a delay 500000, Now = 210919424\n[19869:19869:0318/132307.427007:46918061825:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000022b0 with delay 500\n[19869:19869:0318/132307.427096:46918061904:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000022b0\n[19869:19869:0318/132307.427226:46918062035:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[19869:19869:0318/132307.427327:46918062138: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[19869:19869:0318/132307.427383:46918062194: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[19869:19869:0318/132307.427569:46918062379: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[19869:19869:0318/132307.427855:46918062666: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 (2 ms)\n[2/28] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[19869:19869:0318/132307.428361:46918063179:INFO:protocol-handler.cc(139)] Incoming message: { }\n[19869:19869:0318/132307.428411:46918063220:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[19869:19869:0318/132307.428439:46918063248: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[19869:19869:0318/132307.428685:46918063498:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1566207080 with a delay 10000, Now = 0\n[19869:19869:0318/132307.428718:46918063528:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002970 with delay 10\n[19869:19869:0318/132307.428758:46918063575:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002970\n[19869:19869:0318/132307.428793:46918063601:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[19869:19869:0318/132307.428822:46918063640:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 10000\n[19869:19869:0318/132307.428882:46918063691:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002990 with delay 60\n[19869:19869:0318/132307.428922:46918063732:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000002990\n[19869:19869:0318/132307.428945:46918063754:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[19869:19869:0318/132307.428969:46918063776:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 70000\n[19869:19869:0318/132307.428996:46918063806:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000029b0 with delay 60\n[19869:19869:0318/132307.429025:46918063833:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000029b0\n[19869:19869:0318/132307.429048:46918063855:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[19869:19869:0318/132307.429071:46918063878:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 130000\n[19869:19869:0318/132307.429099:46918063907:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000029d0 with delay 60\n[19869:19869:0318/132307.429142:46918063952:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000029d0\n[19869:19869:0318/132307.429163:46918063971:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[19869:19869:0318/132307.429185:46918063995:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 190000\n[19869:19869:0318/132307.429244:46918064059:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x6020000029f0 with delay 60\n[19869:19869:0318/132307.429294:46918064111:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x6020000029f0\n[19869:19869:0318/132307.429333:46918064145:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[19869:19869:0318/132307.429364:46918064173:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 250000\n[19869:19869:0318/132307.429400:46918064212:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000002a10 with delay 60\n[19869:19869:0318/132307.429431:46918064239:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000002a10\n[19869:19869:0318/132307.429451:46918064259:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[19869:19869:0318/132307.429474:46918064281:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 310000\n[19869:19869:0318/132307.429501:46918064312:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000002a30 with delay 60\n[19869:19869:0318/132307.429533:46918064340:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000002a30\n[19869:19869:0318/132307.429597:46918064410:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[19869:19869:0318/132307.429634:46918064447:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566207080 with a delay 60000, Now = 370000\n[19869:19869:0318/132307.429678:46918064491:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000002a50 with delay 60\n[19869:19869:0318/132307.429720:46918064533:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000002a50\n[19869:19869:0318/132307.429770:46918064588:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (3 ms)\n[4/28] RecurringTaskTest.PeriodicTask (3 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[19869:19869:0318/132307.431210:46918066027:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1566062696 with a delay 10000, Now = 0\n[19869:19869:0318/132307.431267:46918066081:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002ad0 with delay 10\n[19869:19869:0318/132307.431304:46918066112:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002ad0\n[19869:19869:0318/132307.431345:46918066157:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[19869:19869:0318/132307.431387:46918066195:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 50000, Now = 10000\n[19869:19869:0318/132307.431435:46918066245:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002af0 with delay 50\n[19869:19869:0318/132307.431464:46918066273:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000002af0\n[19869:19869:0318/132307.431488:46918066295:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[19869:19869:0318/132307.431513:46918066321:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 149000, Now = 60000\n[19869:19869:0318/132307.431562:46918066371:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000002b10 with delay 149\n[19869:19869:0318/132307.431591:46918066403:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000002b10\n[19869:19869:0318/132307.431619:46918066428:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[19869:19869:0318/132307.431641:46918066449:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 248000, Now = 210000\n[19869:19869:0318/132307.431669:46918066477:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000002b30 with delay 248\n[19869:19869:0318/132307.431701:46918066509:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000002b30\n[19869:19869:0318/132307.431725:46918066532:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[19869:19869:0318/132307.431757:46918066569:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 446000, Now = 460000\n[19869:19869:0318/132307.431790:46918066601:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000002b50 with delay 446\n[19869:19869:0318/132307.431851:46918066659:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000002b50\n[19869:19869:0318/132307.431870:46918066677:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[19869:19869:0318/132307.431892:46918066700:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 842000, Now = 910000\n[19869:19869:0318/132307.431924:46918066736:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000002b70 with delay 842\n[19869:19869:0318/132307.431968:46918066778:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000002b70\n[19869:19869:0318/132307.431998:46918066808:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[19869:19869:0318/132307.432019:46918066827:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 1040000, Now = 1760000\n[19869:19869:0318/132307.432056:46918066864:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000002b90 with delay 1040\n[19869:19869:0318/132307.432096:46918066904:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000002b90\n[19869:19869:0318/132307.432128:46918066938:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[19869:19869:0318/132307.432162:46918066970:INFO:recurring-task.cc(55)] [Retry] Scheduling 1566062696 with a delay 1040000, Now = 2800000\n[19869:19869:0318/132307.432183:46918066991:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000002bb0 with delay 1040\n[19869:19869:0318/132307.432222:46918067028:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000002bb0\n[19869:19869:0318/132307.432241:46918067048: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[19869:19869:0318/132307.433382:46918068193:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1566051432 with a delay 10000, Now = 0\n[19869:19869:0318/132307.433423:46918068235:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002c30 with delay 10\n[19869:19869:0318/132307.433457:46918068266:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002c30\n[19869:19869:0318/132307.433479:46918068286:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[19869:19869:0318/132307.433510:46918068320:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1566051432 with a delay 10000, Now = 10000\n[19869:19869:0318/132307.433572:46918068381:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002c50 with delay 10\n[19869:19869:0318/132307.433600:46918068409:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000002c50\n[19869:19869:0318/132307.433632:46918068444:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (1 ms)\n[6/28] RecurringTaskTest.OneShotTask (1 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[19869:19869:0318/132307.434729:46918069540:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000002cd0 with delay 920\n[19869:19869:0318/132307.434781:46918069588:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002cd0\n[19869:19869:0318/132307.435063:46918069873:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002cf0 with delay 45000\n[19869:19869:0318/132307.435952:46918070767:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002cf0\n[ OK ] ThrottleTest.ThrottlingScripted (2 ms)\n[7/28] ThrottleTest.ThrottlingScripted (2 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[19869:19869:0318/132307.436119:46918070930:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002d70 with delay 990\n[19869:19869:0318/132307.436188:46918070995:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002d70\n[19869:19869:0318/132307.436227:46918071036:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x602000002d90 with delay 1000\n[19869:19869:0318/132307.436284:46918071092:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x602000002d90\n[19869:19869:0318/132307.436308:46918071115:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x602000002db0 with delay 1000\n[19869:19869:0318/132307.436357:46918071164:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x602000002db0\n[19869:19869:0318/132307.436378:46918071185:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x602000002dd0 with delay 1000\n[19869:19869:0318/132307.436425:46918071232:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x602000002dd0\n[19869:19869:0318/132307.436444:46918071251:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002df0 with delay 1000\n[19869:19869:0318/132307.436507:46918071316:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002df0\n[19869:19869:0318/132307.436564:46918071374:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002e10 with delay 1000\n[19869:19869:0318/132307.436616:46918071423:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002e10\n[19869:19869:0318/132307.436639:46918071447:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002e30 with delay 54000\n[19869:19869:0318/132307.438474:46918073287:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002e30\n[19869:19869:0318/132307.438519:46918073328:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002e50 with delay 1000\n[19869:19869:0318/132307.438606:46918073419:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002e50\n[19869:19869:0318/132307.438640:46918073450:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002e70 with delay 1000\n[19869:19869:0318/132307.438707:46918073515:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002e70\n[19869:19869:0318/132307.438734:46918073543:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000002e90 with delay 1000\n[19869:19869:0318/132307.438784:46918073599:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000002e90\n[19869:19869:0318/132307.438833:46918073642:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000002eb0 with delay 1000\n[19869:19869:0318/132307.438883:46918073693:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000002eb0\n[19869:19869:0318/132307.438908:46918073716:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000002ed0 with delay 1000\n[19869:19869:0318/132307.438957:46918073764:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000002ed0\n[19869:19869:0318/132307.438984:46918073792:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002ef0 with delay 1000\n[19869:19869:0318/132307.439064:46918073880:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002ef0\n[19869:19869:0318/132307.439113:46918073924:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002f10 with delay 54000\n[19869:19869:0318/132307.440832:46918075647:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002f10\n[19869:19869:0318/132307.440907:46918075721:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002f30 with delay 1000\n[19869:19869:0318/132307.440995:46918075804:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002f30\n[19869:19869:0318/132307.441022:46918075830:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002f50 with delay 1000\n[19869:19869:0318/132307.441072:46918075879:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002f50\n[19869:19869:0318/132307.441091:46918075898:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002f70 with delay 1000\n[19869:19869:0318/132307.441159:46918075968:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002f70\n[19869:19869:0318/132307.441186:46918075994:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000002f90 with delay 1000\n[19869:19869:0318/132307.441375:46918076184:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000002f90\n[19869:19869:0318/132307.441401:46918076209:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000002fb0 with delay 1000\n[19869:19869:0318/132307.441458:46918076265:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000002fb0\n[19869:19869:0318/132307.441477:46918076284:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000002fd0 with delay 1000\n[19869:19869:0318/132307.441528:46918076334:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000002fd0\n[19869:19869:0318/132307.441575:46918076383:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002ff0 with delay 54000\n[19869:19869:0318/132307.443229:46918078041:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002ff0\n[19869:19869:0318/132307.443289:46918078100:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000003010 with delay 1000\n[19869:19869:0318/132307.443347:46918078155:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000003010\n[19869:19869:0318/132307.443377:46918078188:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000003030 with delay 1000\n[19869:19869:0318/132307.443430:46918078237:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000003030\n[19869:19869:0318/132307.443454:46918078261:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000003050 with delay 1000\n[19869:19869:0318/132307.443501:46918078309:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000003050\n[19869:19869:0318/132307.443521:46918078329:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000003070 with delay 1000\n[19869:19869:0318/132307.443631:46918078441:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000003070\n[19869:19869:0318/132307.443662:46918078473:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000003090 with delay 1000\n[19869:19869:0318/132307.443714:46918078521:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000003090\n[19869:19869:0318/132307.443733:46918078541:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000030b0 with delay 1000\n[19869:19869:0318/132307.443781:46918078588:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000030b0\n[19869:19869:0318/132307.443803:46918078612:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000030d0 with delay 54000\n[19869:19869:0318/132307.445501:46918080313:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000030d0\n[19869:19869:0318/132307.445577:46918080387:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x6020000030f0 with delay 1000\n[19869:19869:0318/132307.445647:46918080456:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x6020000030f0\n[19869:19869:0318/132307.445678:46918080487:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000003110 with delay 1000\n[19869:19869:0318/132307.445727:46918080535:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000003110\n[19869:19869:0318/132307.445747:46918080555:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000003130 with delay 1000\n[19869:19869:0318/132307.445795:46918080602:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000003130\n[19869:19869:0318/132307.445815:46918080640:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000003150 with delay 1000\n[19869:19869:0318/132307.445893:46918080701:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000003150\n[19869:19869:0318/132307.445917:46918080727:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000003170 with delay 1000\n[19869:19869:0318/132307.445980:46918080787:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000003170\n[19869:19869:0318/132307.446019:46918080829:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000003190 with delay 1000\n[19869:19869:0318/132307.446071:46918080878:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000003190\n[19869:19869:0318/132307.446091:46918080900:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000031b0 with delay 54000\n[19869:19869:0318/132307.447746:46918082557:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000031b0\n[ OK ] ThrottleTest.ThrottlingStorm (11 ms)\n[8/28] ThrottleTest.ThrottlingStorm (11 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[19870:19870:0318/132307.428702:46918063530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0\n[19870:19870:0318/132307.429093:46918063905:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0\n[19870:19870:0318/132307.429434:46918064252: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[19870:19870:0318/132307.429497:46918064308:INFO:recurring-task.cc(55)] [Startup] Scheduling 24488 with a delay 500000, Now = 210919424\n[19870:19870:0318/132307.429535:46918064372:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 500\n[19870:19870:0318/132307.429653:46918064465:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001e90\n[19870:19870:0318/132307.429910:46918064730: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[19870:19870:0318/132307.431084:46918065902: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[19870:19870:0318/132307.431524:46918066337:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ad0 with delay 0\n[19870:19870:0318/132307.431613:46918066422:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002af0 with delay 0\n[19870:19870:0318/132307.431653:46918066463:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b10 with delay 0\n[19870:19870:0318/132307.431713:46918066525:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b30 with delay 0\n[19870:19870:0318/132307.431746:46918066555:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b50 with delay 0\n[19870:19870:0318/132307.431816:46918066626:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b70 with delay 0\n[19870:19870:0318/132307.432151:46918066962:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002ad0\n[19870:19870:0318/132307.432291:46918067101: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[19870:19870:0318/132307.432352:46918067162:INFO:recurring-task.cc(55)] [Send-info] Scheduling 36008 with a delay 500000, Now = 210919424\n[19870:19870:0318/132307.432392:46918067202:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002d10 with delay 500\n[19870:19870:0318/132307.432425:46918067234:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002af0\n[19870:19870:0318/132307.432455:46918067266:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b10\n[19870:19870:0318/132307.432482:46918067291:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b30\n[19870:19870:0318/132307.432510:46918067318:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b50\n[19870:19870:0318/132307.432575:46918067385:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b70\n[19870:19870:0318/132307.432622:46918067434:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[19870:19870:0318/132307.432707:46918067518:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002d10\n[19870:19870:0318/132307.432862:46918067671:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[19870:19870:0318/132307.433337:46918068147: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 (3 ms)\n[11/28] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[19870:19870:0318/132307.435038:46918069850:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } invalidation_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[12/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[19870:19870:0318/132307.435650:46918070465: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[19870:19870:0318/132307.435726:46918070535: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[19870:19870:0318/132307.435830:46918070640: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[19870:19870:0318/132307.435932:46918070741:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[13/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[19870:19870:0318/132307.436452:46918071262: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[19870:19870:0318/132307.436618:46918071428: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 (0 ms)\n[14/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[19870:19870:0318/132307.437090:46918071900: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 (1 ms)\n[15/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[19870:19870:0318/132307.437645:46918072464: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[19870:19870:0318/132307.437721:46918072535:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004850 with delay 0\n[19870:19870:0318/132307.437763:46918072577:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004850\n[19870:19870:0318/132307.437852:46918072669: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[19870:19870:0318/132307.437919:46918072733:INFO:recurring-task.cc(55)] [Send-info] Scheduling 67112 with a delay 500000, Now = 210919424\n[19870:19870:0318/132307.437966:46918072782:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004870 with delay 500\n[19870:19870:0318/132307.438070:46918072886:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004870\n[19870:19870:0318/132307.438118:46918072932:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (37 ms)\n[16/28] ProtocolHandlerTest.ConfigMessage (37 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[19870:19870:0318/132307.474646:46918109463: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[19870:19870:0318/132307.475183:46918109993: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[19867:19867:0318/132307.412139:46918046952:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 0\n[19867:19867:0318/132307.412499:46918047312:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.412809:46918047619:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002550 with delay 0\n[19867:19867:0318/132307.412849:46918047660:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002030\n[19867:19867:0318/132307.412880:46918047696:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002550\n[19867:19867:0318/132307.412978:46918047792:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.413065:46918047880:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0\n[19867:19867:0318/132307.413114:46918047922:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002610\n[19867:19867:0318/132307.413139:46918047948:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.413164:46918047972:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002650 with delay 0\n[19867:19867:0318/132307.413218:46918048032:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002650\n[19867:19867:0318/132307.413263:46918048076:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.413310:46918048118:INFO:recurring-task.cc(55)] [Startup] Scheduling 24744 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.413340:46918048149:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002670 with delay 0\n[19867:19867:0318/132307.413370:46918048181:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002670\n[19867:19867:0318/132307.413493:46918048300:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6805010003660280951\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.413523:46918048332:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 25000 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.413592:46918048404:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002690 with delay 500\n[19867:19867:0318/132307.413627:46918048436:INFO:recurring-task.cc(55)] [Retry] Scheduling 24744 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.413654:46918048462:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000026b0 with delay 60000\n[19867:19867:0318/132307.413740:46918048549:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002690\n[19867:19867:0318/132307.413770:46918048583:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.413880:46918048690:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.414041:46918048856: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: \"-6805010003660280951\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.414281:46918049090:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002750 with delay 0\n[19867:19867:0318/132307.414326:46918049135:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002750\n[19867:19867:0318/132307.414510:46918049318:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6805010003660280951\" 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[19867:19867:0318/132307.414625:46918049437:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6805010003660280951\"\n[19867:19867:0318/132307.414670:46918049479:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.414706:46918049526:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13448 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.414755:46918049564:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002770 with delay 1200000\n[19867:19867:0318/132307.414798:46918049607:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.414952:46918049760:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.415000:46918049810:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 9672 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.415025:46918049833:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002990 with delay 0\n[19867:19867:0318/132307.415105:46918049913: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[19867:19867:0318/132307.415139:46918049948:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002990\n[19867:19867:0318/132307.415220:46918050031:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a50 with delay 0\n[19867:19867:0318/132307.415257:46918050065:INFO:recurring-task.cc(55)] [Retry] Scheduling 9672 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.415285:46918050092:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a90 with delay 10000\n[19867:19867:0318/132307.415307:46918050114:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002a50\n[19867:19867:0318/132307.415344:46918050152: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[19867:19867:0318/132307.416120:46918050930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000032f0 with delay 0\n[19867:19867:0318/132307.416184:46918050993: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[19867:19867:0318/132307.416670:46918051485:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 0\n[19867:19867:0318/132307.416740:46918051556:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.417022:46918051832:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000041f0 with delay 0\n[19867:19867:0318/132307.417061:46918051870:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b90\n[19867:19867:0318/132307.417092:46918051900:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000041f0\n[19867:19867:0318/132307.417142:46918051952:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.417230:46918052047:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042b0 with delay 0\n[19867:19867:0318/132307.417299:46918052108:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042b0\n[19867:19867:0318/132307.417324:46918052133:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.417357:46918052165:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042f0 with delay 0\n[19867:19867:0318/132307.417393:46918052205:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042f0\n[19867:19867:0318/132307.417423:46918052231:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.417469:46918052277:INFO:recurring-task.cc(55)] [Startup] Scheduling 48680 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.417496:46918052306:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004310 with delay 0\n[19867:19867:0318/132307.417523:46918052330:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004310\n[19867:19867:0318/132307.417606:46918052414:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1342756700922908097\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.417649:46918052458:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 48936 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.417680:46918052489:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004330 with delay 500\n[19867:19867:0318/132307.417714:46918052523:INFO:recurring-task.cc(55)] [Retry] Scheduling 48680 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.417750:46918052562:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004350 with delay 60000\n[19867:19867:0318/132307.417841:46918052650:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004330\n[19867:19867:0318/132307.417870:46918052687:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.417921:46918052730:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.418056:46918052865: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: \"1342756700922908097\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.418160:46918052971:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000043f0 with delay 0\n[19867:19867:0318/132307.418187:46918052996:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000043f0\n[19867:19867:0318/132307.418290:46918053101:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1342756700922908097\" 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[19867:19867:0318/132307.418345:46918053153:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1342756700922908097\"\n[19867:19867:0318/132307.418375:46918053183:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.418405:46918053214:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15736 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.418432:46918053240:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004410 with delay 1200000\n[19867:19867:0318/132307.418467:46918053275:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.418649:46918053464:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.418702:46918053529:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 14088 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.418767:46918053583:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004630 with delay 0\n[19867:19867:0318/132307.418837:46918053648: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[19867:19867:0318/132307.418892:46918053701:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004630\n[19867:19867:0318/132307.418964:46918053774:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000046f0 with delay 0\n[19867:19867:0318/132307.419007:46918053815:INFO:recurring-task.cc(55)] [Retry] Scheduling 14088 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.419039:46918053849:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004730 with delay 10000\n[19867:19867:0318/132307.419065:46918053873:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000046f0\n[19867:19867:0318/132307.419085:46918053903:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.419174:46918053984:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004750 with delay 0\n[19867:19867:0318/132307.419229:46918054037:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000004750\n[19867:19867:0318/132307.419266:46918054076:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[19867:19867:0318/132307.419304:46918054112:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[19867:19867:0318/132307.419332:46918054140:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[19867:19867:0318/132307.419405:46918054214:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 48936 with a delay 500000, Now = 211469424\n[19867:19867:0318/132307.419434:46918054243:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004770 with delay 500\n[19867:19867:0318/132307.419472:46918054281:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 48808 with a delay 60000000, Now = 211469424\n[19867:19867:0318/132307.419502:46918054311:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004790 with delay 60000\n[19867:19867:0318/132307.419601:46918054410:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004770\n[19867:19867:0318/132307.419628:46918054439:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.419675:46918054484:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.419699:46918054506:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19867:19867:0318/132307.419855:46918054664: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[19867:19867:0318/132307.419991:46918054803:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.420071:46918054880:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000004830 with delay 0\n[19867:19867:0318/132307.420102:46918054910:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004830\n[19867:19867:0318/132307.420291:46918055100: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[19867:19867:0318/132307.420380:46918055191: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[19867:19867:0318/132307.420448:46918055255:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[19867:19867:0318/132307.420566:46918055375:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[19867:19867:0318/132307.420644:46918055453:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[19867:19867:0318/132307.421082:46918055894: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[19867:19867:0318/132307.422683:46918057496:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005410 with delay 0\n[19867:19867:0318/132307.422742:46918057550:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.423077:46918057888:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005af0 with delay 0\n[19867:19867:0318/132307.423112:46918057939:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005410\n[19867:19867:0318/132307.423163:46918057972:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005af0\n[19867:19867:0318/132307.423216:46918058026:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.423266:46918058075:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bb0 with delay 0\n[19867:19867:0318/132307.423299:46918058108:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bb0\n[19867:19867:0318/132307.423320:46918058127:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.423348:46918058156:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bf0 with delay 0\n[19867:19867:0318/132307.423374:46918058183:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bf0\n[19867:19867:0318/132307.423395:46918058203:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.423426:46918058237:INFO:recurring-task.cc(55)] [Startup] Scheduling 79784 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.423467:46918058276:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c10 with delay 0\n[19867:19867:0318/132307.423497:46918058304:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005c10\n[19867:19867:0318/132307.423584:46918058392:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3130798615300504045\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.423616:46918058426:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 80040 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.423644:46918058453:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c30 with delay 500\n[19867:19867:0318/132307.423673:46918058481:INFO:recurring-task.cc(55)] [Retry] Scheduling 79784 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.423697:46918058508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c50 with delay 60000\n[19867:19867:0318/132307.423742:46918058550:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005c30\n[19867:19867:0318/132307.423769:46918058577:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.423807:46918058615:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.423915:46918058723: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: \"-3130798615300504045\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.424000:46918058808:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005cf0 with delay 0\n[19867:19867:0318/132307.424024:46918058833:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005cf0\n[19867:19867:0318/132307.424151:46918058961:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3130798615300504045\" 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[19867:19867:0318/132307.424213:46918059024:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3130798615300504045\"\n[19867:19867:0318/132307.424253:46918059062:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.424282:46918059090:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20840 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.424308:46918059117:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005d10 with delay 1200000\n[19867:19867:0318/132307.424337:46918059146:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.424465:46918059275:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.424505:46918059315:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 20808 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.424532:46918059366:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005f30 with delay 0\n[19867:19867:0318/132307.424613:46918059421: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[19867:19867:0318/132307.424670:46918059478:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005f30\n[19867:19867:0318/132307.424740:46918059550:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005ff0 with delay 0\n[19867:19867:0318/132307.424788:46918059598:INFO:recurring-task.cc(55)] [Retry] Scheduling 20808 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.424826:46918059635:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006030 with delay 10000\n[19867:19867:0318/132307.424851:46918059659:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005ff0\n[19867:19867:0318/132307.424873:46918059681:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.424921:46918059732:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.424979:46918059788:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006050 with delay 0\n[19867:19867:0318/132307.425007:46918059820:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006050\n[19867:19867:0318/132307.425189:46918059999: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[19867:19867:0318/132307.425323:46918060132: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[19867:19867:0318/132307.425395:46918060203: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[19867:19867:0318/132307.425490:46918060298: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[19867:19867:0318/132307.425585:46918060398: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[19867:19867:0318/132307.425689:46918060502:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006430 with delay 0\n[19867:19867:0318/132307.425739:46918060553:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006450 with delay 0\n[19867:19867:0318/132307.425780:46918060595:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006470 with delay 0\n[19867:19867:0318/132307.425833:46918060647:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006430\n[19867:19867:0318/132307.425904:46918060717:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 80040 with a delay 500000, Now = 211519424\n[19867:19867:0318/132307.425950:46918060767:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006490 with delay 500\n[19867:19867:0318/132307.426008:46918060821:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006450\n[19867:19867:0318/132307.426054:46918060866:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006470\n[19867:19867:0318/132307.426117:46918060930:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x602000006490\n[19867:19867:0318/132307.426160:46918060974:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.426225:46918061040:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.426260:46918061070:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19867:19867:0318/132307.426418:46918061228: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[19867:19867:0318/132307.427109:46918061919:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006d70 with delay 0\n[19867:19867:0318/132307.427171:46918061985:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.427415:46918062225:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0\n[19867:19867:0318/132307.427449:46918062258:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006d70\n[19867:19867:0318/132307.427474:46918062281:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290\n[19867:19867:0318/132307.427533:46918062375:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.427628:46918062438:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007350 with delay 0\n[19867:19867:0318/132307.427663:46918062472:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007350\n[19867:19867:0318/132307.427688:46918062495:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.427738:46918062549:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007390 with delay 0\n[19867:19867:0318/132307.427776:46918062585:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007390\n[19867:19867:0318/132307.427801:46918062609:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.427838:46918062646:INFO:recurring-task.cc(55)] [Startup] Scheduling 109480 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.427866:46918062674:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073b0 with delay 0\n[19867:19867:0318/132307.427892:46918062700:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000073b0\n[19867:19867:0318/132307.427960:46918062770:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2245795308147681999\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.427997:46918062806:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 109736 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.428026:46918062837:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073d0 with delay 500\n[19867:19867:0318/132307.428052:46918062869:INFO:recurring-task.cc(55)] [Retry] Scheduling 109480 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.428098:46918062906:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073f0 with delay 60000\n[19867:19867:0318/132307.428154:46918062965:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000073d0\n[19867:19867:0318/132307.428183:46918062991:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.428221:46918063030:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.428330:46918063141: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: \"2245795308147681999\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.428442:46918063251:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007490 with delay 0\n[19867:19867:0318/132307.428474:46918063284:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007490\n[19867:19867:0318/132307.428598:46918063408:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2245795308147681999\" 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[19867:19867:0318/132307.428653:46918063461:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2245795308147681999\"\n[19867:19867:0318/132307.428681:46918063491:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.428733:46918063542:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 24888 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.428787:46918063602:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000074b0 with delay 1200000\n[19867:19867:0318/132307.428834:46918063646:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.428976:46918063786:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.429015:46918063824:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 26952 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.429045:46918063855:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076d0 with delay 0\n[19867:19867:0318/132307.429095:46918063905: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[19867:19867:0318/132307.429132:46918063941:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000076d0\n[19867:19867:0318/132307.429190:46918063999:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007790 with delay 0\n[19867:19867:0318/132307.429271:46918064089:INFO:recurring-task.cc(55)] [Retry] Scheduling 26952 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.429323:46918064131:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000077d0 with delay 10000\n[19867:19867:0318/132307.429354:46918064162:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007790\n[19867:19867:0318/132307.429375:46918064183:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.429428:46918064237:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.429470:46918064279:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000077f0 with delay 0\n[19867:19867:0318/132307.429497:46918064305:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000077f0\n[19867:19867:0318/132307.429638:46918064447: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[19867:19867:0318/132307.429707:46918064524: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[19867:19867:0318/132307.429749:46918064558:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[19867:19867:0318/132307.429781:46918064589:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 109736 with a delay 500000, Now = 211469424\n[19867:19867:0318/132307.429810:46918064620:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007810 with delay 500\n[19867:19867:0318/132307.429837:46918064645:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[19867:19867:0318/132307.430033:46918064842: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[19867:19867:0318/132307.430111:46918064919:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007810\n[19867:19867:0318/132307.430139:46918064949:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.430200:46918065010:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.430252:46918065061:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19867:19867:0318/132307.430576:46918065386: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[19867:19867:0318/132307.430929:46918065739: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[19867:19867:0318/132307.432503:46918067314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000080f0 with delay 0\n[19867:19867:0318/132307.432577:46918067385:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.432815:46918067624:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000086b0 with delay 0\n[19867:19867:0318/132307.432847:46918067656:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000080f0\n[19867:19867:0318/132307.432875:46918067683:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000086b0\n[19867:19867:0318/132307.432926:46918067734:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.432970:46918067779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008770 with delay 0\n[19867:19867:0318/132307.433011:46918067819:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008770\n[19867:19867:0318/132307.433032:46918067839:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.433064:46918067873:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0\n[19867:19867:0318/132307.433091:46918067899:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0\n[19867:19867:0318/132307.433112:46918067920:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.433138:46918067946:INFO:recurring-task.cc(55)] [Startup] Scheduling 136744 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.433168:46918067977:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087d0 with delay 0\n[19867:19867:0318/132307.433193:46918068020:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087d0\n[19867:19867:0318/132307.433301:46918068111:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3419845418933118192\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.433336:46918068145:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 137000 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.433363:46918068172:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087f0 with delay 500\n[19867:19867:0318/132307.433391:46918068199:INFO:recurring-task.cc(55)] [Retry] Scheduling 136744 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.433416:46918068224:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008810 with delay 60000\n[19867:19867:0318/132307.433453:46918068261:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000087f0\n[19867:19867:0318/132307.433476:46918068285:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.433526:46918068336:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.433704:46918068524: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: \"-3419845418933118192\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.433834:46918068648:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088b0 with delay 0\n[19867:19867:0318/132307.433873:46918068687:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000088b0\n[19867:19867:0318/132307.434016:46918068830:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3419845418933118192\" 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[19867:19867:0318/132307.434088:46918068902:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3419845418933118192\"\n[19867:19867:0318/132307.434128:46918068941:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.434173:46918068987:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28408 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.434216:46918069025:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088d0 with delay 1200000\n[19867:19867:0318/132307.434257:46918069066:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.434366:46918069174:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.434393:46918069202:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 32328 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.434420:46918069228:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008af0 with delay 0\n[19867:19867:0318/132307.434461:46918069269: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[19867:19867:0318/132307.434504:46918069314:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008af0\n[19867:19867:0318/132307.434601:46918069410:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bb0 with delay 0\n[19867:19867:0318/132307.434637:46918069445:INFO:recurring-task.cc(55)] [Retry] Scheduling 32328 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.434661:46918069472:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bf0 with delay 10000\n[19867:19867:0318/132307.434686:46918069495:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008bb0\n[19867:19867:0318/132307.434707:46918069522:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.434757:46918069567:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.434797:46918069606:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000008c10 with delay 0\n[19867:19867:0318/132307.434832:46918069640:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000008c10\n[19867:19867:0318/132307.434926:46918069735: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[19867:19867:0318/132307.434994:46918069803: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[19867:19867:0318/132307.435063:46918069871:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[19867:19867:0318/132307.435360:46918070170: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[19867:19867:0318/132307.436813:46918071623:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009570 with delay 0\n[19867:19867:0318/132307.436872:46918071680:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.437121:46918071930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009bf0 with delay 0\n[19867:19867:0318/132307.437151:46918071960:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009570\n[19867:19867:0318/132307.437182:46918071991:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009bf0\n[19867:19867:0318/132307.437277:46918072089:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.437344:46918072153:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cb0 with delay 0\n[19867:19867:0318/132307.437377:46918072185:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cb0\n[19867:19867:0318/132307.437409:46918072217:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.437450:46918072258:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cf0 with delay 0\n[19867:19867:0318/132307.437476:46918072290:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cf0\n[19867:19867:0318/132307.437505:46918072314:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.437534:46918072368:INFO:recurring-task.cc(55)] [Startup] Scheduling 159400 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.437588:46918072398:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d10 with delay 0\n[19867:19867:0318/132307.437615:46918072423:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009d10\n[19867:19867:0318/132307.437691:46918072500:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6115535642281850032\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.437734:46918072543:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 159656 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.437764:46918072572:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d30 with delay 500\n[19867:19867:0318/132307.437787:46918072596:INFO:recurring-task.cc(55)] [Retry] Scheduling 159400 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.437814:46918072622:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d50 with delay 60000\n[19867:19867:0318/132307.437857:46918072666:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009d30\n[19867:19867:0318/132307.437885:46918072692:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.437931:46918072740:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.438073:46918072882: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: \"6115535642281850032\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.438205:46918073017:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009df0 with delay 0\n[19867:19867:0318/132307.438242:46918073051:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009df0\n[19867:19867:0318/132307.438353:46918073162:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6115535642281850032\" 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[19867:19867:0318/132307.438398:46918073210:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6115535642281850032\"\n[19867:19867:0318/132307.438432:46918073241:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.438465:46918073274:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31576 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.438493:46918073302:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009e10 with delay 1200000\n[19867:19867:0318/132307.438522:46918073331:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.438696:46918073509:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.438740:46918073550:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 35976 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.438769:46918073578:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a030 with delay 0\n[19867:19867:0318/132307.438812:46918073621: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[19867:19867:0318/132307.438848:46918073657:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a030\n[19867:19867:0318/132307.438905:46918073714:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a0f0 with delay 0\n[19867:19867:0318/132307.438939:46918073748:INFO:recurring-task.cc(55)] [Retry] Scheduling 35976 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.438963:46918073772:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a130 with delay 10000\n[19867:19867:0318/132307.439001:46918073809:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a0f0\n[19867:19867:0318/132307.439035:46918073844:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.439077:46918073886:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a150 with delay 0\n[19867:19867:0318/132307.439104:46918073913:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000a150\n[19867:19867:0318/132307.439142:46918073951:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[19867:19867:0318/132307.439201:46918074010:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 159656 with a delay 500000, Now = 211469424\n[19867:19867:0318/132307.439231:46918074041:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a170 with delay 500\n[19867:19867:0318/132307.439264:46918074073:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 159528 with a delay 60000000, Now = 211469424\n[19867:19867:0318/132307.439291:46918074100:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a190 with delay 60000\n[19867:19867:0318/132307.439341:46918074149:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a170\n[19867:19867:0318/132307.439363:46918074170:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.439405:46918074214:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.439428:46918074236:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19867:19867:0318/132307.439575:46918074385: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[19867:19867:0318/132307.439655:46918074464:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.439697:46918074508:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000a230 with delay 0\n[19867:19867:0318/132307.439746:46918074559:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a230\n[19867:19867:0318/132307.439868:46918074677: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[19867:19867:0318/132307.439946:46918074755: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[19867:19867:0318/132307.439973:46918074782:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[19867:19867:0318/132307.440060:46918074868:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[19867:19867:0318/132307.440396:46918075206:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000a130\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[19867:19867:0318/132307.441993:46918076808:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ac90 with delay 0\n[19867:19867:0318/132307.442069:46918076881:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.442324:46918077135:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b1b0 with delay 0\n[19867:19867:0318/132307.442360:46918077168:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ac90\n[19867:19867:0318/132307.442385:46918077193:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b1b0\n[19867:19867:0318/132307.442438:46918077246:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.442483:46918077294:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b270 with delay 0\n[19867:19867:0318/132307.442516:46918077324:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b270\n[19867:19867:0318/132307.442584:46918077393:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.442625:46918077434:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2b0 with delay 0\n[19867:19867:0318/132307.442653:46918077463:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2b0\n[19867:19867:0318/132307.442676:46918077484:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.442705:46918077520:INFO:recurring-task.cc(55)] [Startup] Scheduling 187816 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.442742:46918077552:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2d0 with delay 0\n[19867:19867:0318/132307.442767:46918077575:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2d0\n[19867:19867:0318/132307.442819:46918077628:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3996065693176108506\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.442850:46918077658:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 188072 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.442884:46918077696:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2f0 with delay 500\n[19867:19867:0318/132307.442922:46918077735:INFO:recurring-task.cc(55)] [Retry] Scheduling 187816 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.442974:46918077788:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b310 with delay 60000\n[19867:19867:0318/132307.443027:46918077835:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b2f0\n[19867:19867:0318/132307.443050:46918077858:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.443087:46918077899:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.443225:46918078044: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: \"-3996065693176108506\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.443337:46918078145:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3b0 with delay 0\n[19867:19867:0318/132307.443365:46918078174:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b3b0\n[19867:19867:0318/132307.443464:46918078272:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3996065693176108506\" 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[19867:19867:0318/132307.443515:46918078324:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3996065693176108506\"\n[19867:19867:0318/132307.443576:46918078389:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.443624:46918078436:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 34920 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.443670:46918078483:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3d0 with delay 1200000\n[19867:19867:0318/132307.443719:46918078533:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.443902:46918078718:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.443956:46918078769:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 41352 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.443999:46918078813:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b5f0 with delay 0\n[19867:19867:0318/132307.444064:46918078878: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[19867:19867:0318/132307.444115:46918078928:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b5f0\n[19867:19867:0318/132307.444197:46918079012:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6b0 with delay 0\n[19867:19867:0318/132307.444238:46918079046:INFO:recurring-task.cc(55)] [Retry] Scheduling 41352 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.444262:46918079070:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6f0 with delay 10000\n[19867:19867:0318/132307.444285:46918079092:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b6b0\n[19867:19867:0318/132307.444305:46918079112:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.444350:46918079159:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b710 with delay 0\n[19867:19867:0318/132307.444381:46918079212:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000b710\n[19867:19867:0318/132307.444476:46918079291:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[19867:19867:0318/132307.444561:46918079372:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 188072 with a delay 500000, Now = 211469424\n[19867:19867:0318/132307.444609:46918079419:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b730 with delay 500\n[19867:19867:0318/132307.444638:46918079445:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 187944 with a delay 60000000, Now = 211469424\n[19867:19867:0318/132307.444664:46918079473:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b750 with delay 60000\n[19867:19867:0318/132307.444722:46918079530:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000b730\n[19867:19867:0318/132307.444747:46918079567:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.444808:46918079617:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.444832:46918079640:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19867:19867:0318/132307.444946:46918079755: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[19867:19867:0318/132307.445276:46918080085:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000b6f0\n[19867:19867:0318/132307.446274:46918081085:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000b310\n[19867:19867:0318/132307.446335:46918081143:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000b750\n[19867:19867:0318/132307.446392:46918081201: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[19867:19867:0318/132307.446425:46918081234:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[19867:19867:0318/132307.446491:46918081299: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[19867:19867:0318/132307.446523:46918081333:INFO:recurring-task.cc(55)] [Send-info] Scheduling 188072 with a delay 500000, Now = 271469424\n[19867:19867:0318/132307.446586:46918081395:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b7f0 with delay 500\n[19867:19867:0318/132307.446612:46918081420:INFO:recurring-task.cc(55)] [Retry] Scheduling 187944 with a delay 60000000, Now = 271469424\n[19867:19867:0318/132307.446642:46918081451:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b810 with delay 60000\n[19867:19867:0318/132307.446679:46918081487:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000b7f0\n[19867:19867:0318/132307.446704:46918081548:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.446790:46918081599:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.446814:46918081622:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19867:19867:0318/132307.446959:46918081768: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 (7 ms)\n[26/28] InvalidationClientImplTest.NetworkTimeouts (7 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[19867:19867:0318/132307.448535:46918083373:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c0f0 with delay 0\n[19867:19867:0318/132307.448619:46918083429:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.448831:46918083641:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c610 with delay 0\n[19867:19867:0318/132307.448868:46918083676:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c0f0\n[19867:19867:0318/132307.448895:46918083705:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c610\n[19867:19867:0318/132307.448944:46918083752:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.448991:46918083799:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6d0 with delay 0\n[19867:19867:0318/132307.449031:46918083840:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6d0\n[19867:19867:0318/132307.449053:46918083861:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.449080:46918083889:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c710 with delay 0\n[19867:19867:0318/132307.449103:46918083911:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c710\n[19867:19867:0318/132307.449122:46918083929:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.449153:46918083962:INFO:recurring-task.cc(55)] [Startup] Scheduling 216744 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.449177:46918083986:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c730 with delay 0\n[19867:19867:0318/132307.449229:46918084037:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c730\n[19867:19867:0318/132307.449301:46918084110:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3726275505793753860\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.449333:46918084143:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 217000 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.449360:46918084168:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c750 with delay 500\n[19867:19867:0318/132307.449413:46918084222:INFO:recurring-task.cc(55)] [Retry] Scheduling 216744 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.449442:46918084251:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c770 with delay 60000\n[19867:19867:0318/132307.449476:46918084283:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c750\n[19867:19867:0318/132307.449501:46918084310:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.449538:46918084370:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.449683:46918084493: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: \"3726275505793753860\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.449791:46918084600:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c810 with delay 0\n[19867:19867:0318/132307.449819:46918084634:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c810\n[19867:19867:0318/132307.449959:46918084769:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3726275505793753860\" 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[19867:19867:0318/132307.450008:46918084817:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3726275505793753860\"\n[19867:19867:0318/132307.450037:46918084846:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.450064:46918084875:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 37560 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.450092:46918084901:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c830 with delay 1200000\n[19867:19867:0318/132307.450123:46918084934:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.450243:46918085053:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.450281:46918085089:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 47304 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.450306:46918085114:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ca50 with delay 0\n[19867:19867:0318/132307.450348:46918085155: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[19867:19867:0318/132307.450394:46918085204:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ca50\n[19867:19867:0318/132307.450450:46918085259:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb10 with delay 0\n[19867:19867:0318/132307.450484:46918085294:INFO:recurring-task.cc(55)] [Retry] Scheduling 47304 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.450511:46918085321:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb50 with delay 10000\n[19867:19867:0318/132307.450535:46918085368:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cb10\n[19867:19867:0318/132307.450591:46918085402:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.450634:46918085443:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.450670:46918085479:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000cb70 with delay 0\n[19867:19867:0318/132307.450706:46918085522:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000cb70\n[19867:19867:0318/132307.450782:46918085591: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[19867:19867:0318/132307.451043:46918085853:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000cb50\n[19867:19867:0318/132307.451914:46918086725: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[19867:19867:0318/132307.452598:46918087410:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0\n[19867:19867:0318/132307.452655:46918087464:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19867:19867:0318/132307.452846:46918087662:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d8f0 with delay 0\n[19867:19867:0318/132307.452910:46918087720:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0\n[19867:19867:0318/132307.452937:46918087745:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d8f0\n[19867:19867:0318/132307.452996:46918087806:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19867:19867:0318/132307.453042:46918087851:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9b0 with delay 0\n[19867:19867:0318/132307.453073:46918087882:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9b0\n[19867:19867:0318/132307.453094:46918087902:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19867:19867:0318/132307.453120:46918087929:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9f0 with delay 0\n[19867:19867:0318/132307.453145:46918087952:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9f0\n[19867:19867:0318/132307.453164:46918087972:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19867:19867:0318/132307.453194:46918088023:INFO:recurring-task.cc(55)] [Startup] Scheduling 238376 with a delay 0, Now = 210919424\n[19867:19867:0318/132307.453248:46918088056:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da10 with delay 0\n[19867:19867:0318/132307.453271:46918088079:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000da10\n[19867:19867:0318/132307.453337:46918088145:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"982264618349404065\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19867:19867:0318/132307.453367:46918088176:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 238632 with a delay 500000, Now = 210919424\n[19867:19867:0318/132307.453409:46918088218:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da30 with delay 500\n[19867:19867:0318/132307.453434:46918088243:INFO:recurring-task.cc(55)] [Retry] Scheduling 238376 with a delay 60000000, Now = 210919424\n[19867:19867:0318/132307.453460:46918088269:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da50 with delay 60000\n[19867:19867:0318/132307.453505:46918088316:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000da30\n[19867:19867:0318/132307.453532:46918088340:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.453597:46918088405:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19867:19867:0318/132307.453707:46918088523: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: \"982264618349404065\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19867:19867:0318/132307.453820:46918088629:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000daf0 with delay 0\n[19867:19867:0318/132307.453847:46918088656:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000daf0\n[19867:19867:0318/132307.453966:46918088776:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"982264618349404065\" 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[19867:19867:0318/132307.454014:46918088822:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"982264618349404065\"\n[19867:19867:0318/132307.454043:46918088852:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19867:19867:0318/132307.454074:46918088883:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 40024 with a delay 1200000000, Now = 211419424\n[19867:19867:0318/132307.454102:46918088921:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000db10 with delay 1200000\n[19867:19867:0318/132307.454151:46918088960:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19867:19867:0318/132307.454267:46918089077:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.454299:46918089108:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 67272 with a delay 0, Now = 211419424\n[19867:19867:0318/132307.454325:46918089134:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000dd30 with delay 0\n[19867:19867:0318/132307.454369:46918089177: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[19867:19867:0318/132307.454402:46918089210:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000dd30\n[19867:19867:0318/132307.454464:46918089273:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ddf0 with delay 0\n[19867:19867:0318/132307.454502:46918089313:INFO:recurring-task.cc(55)] [Retry] Scheduling 67272 with a delay 10000000, Now = 211419424\n[19867:19867:0318/132307.454582:46918089391:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000de30 with delay 10000\n[19867:19867:0318/132307.454612:46918089420:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ddf0\n[19867:19867:0318/132307.454634:46918089443:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19867:19867:0318/132307.454917:46918089725:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000de30\n[19867:19867:0318/132307.455874:46918090684:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000da50\n[19867:19867:0318/132307.476068:46918110882:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000db10\n[19867:19867:0318/132307.476182:46918110992:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.476239:46918111048:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19867:19867:0318/132307.476277:46918111087:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[19867:19867:0318/132307.476464:46918111274: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[19867:19867:0318/132307.476532:46918111374:INFO:recurring-task.cc(55)] [Send-info] Scheduling 238632 with a delay 500000, Now = 1411419424\n[19867:19867:0318/132307.476601:46918111410:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de50 with delay 500\n[19867:19867:0318/132307.476652:46918111462:INFO:recurring-task.cc(55)] [Retry] Scheduling 40024 with a delay 1200000000, Now = 1411419424\n[19867:19867:0318/132307.476683:46918111493:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de70 with delay 1200000\n[19867:19867:0318/132307.476737:46918111545:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000de50\n[19867:19867:0318/132307.476762:46918111571:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.476830:46918111641:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19867:19867:0318/132307.476856:46918111666:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19867:19867:0318/132307.477067:46918111877: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 (26 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (26 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "8b0f0cbed293d298f91184c63fc116cfc4ea9c57", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43ab4a4827b6ee11", "server_versions": [ "4201-b04f7f8" ], "started_ts": "2019-03-18T20:23:02.144015", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux ASan LSan Tests (1)", "buildnumber:58476", "cpu:x86-64", "data:92bae042efa4e707f1e9080f514af067db1848b9", "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:244982571b3ecfa1c8214e8abc2737d6497fad55", "user:None" ], "task_id": "43ac81b2d0319910" } ] }