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

{ "shards": [ { "bot_dimensions": [ { "key": "caches", "value": [ "swarming_module_cache_vpython" ] }, { "key": "cores", "value": [ "8" ] }, { "key": "cpu", "value": [ "x86", "x86-64", "x86-64-Broadwell_GCE", "x86-64-avx2" ] }, { "key": "gce", "value": [ "1" ] }, { "key": "gpu", "value": [ "none" ] }, { "key": "id", "value": [ "gce-trusty-e833d7b0-us-east1-b-0dlp" ] }, { "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": "gce-trusty-e833d7b0-us-east1-b-0dlp", "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-16T05:36:26.400850", "cost_saved_usd": 0.0009707298813316568, "created_ts": "2019-03-17T07:56:38.205478", "deduped_from": "439dd1bf53f48311", "duration": 1.1726479530334473, "modified_ts": "2019-03-17T07:56:38.221334", "name": "cacheinvalidation_unittests/Ubuntu-14.04/26eb11a34f/Linux ChromiumOS MSan Tests/11842", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n MSAN_OPTIONS=symbolize=0 handle_abort=1\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/io4pbpnB/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[20421:20421:0315/223624.590345:7731296563:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 0\n[20421:20421:0315/223624.590515:7731296666:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000540\n[20421:20421:0315/223624.590930:7731297079: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[20421:20421:0315/223624.591000:7731297157:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2120 with a delay 500000, Now = 210919424\n[20421:20421:0315/223624.591047:7731297196:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000560 with delay 500\n[20421:20421:0315/223624.591101:7731297250:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000560\n[20421:20421:0315/223624.591215:7731297364:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[20421:20421:0315/223624.591259:7731297407:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (9 ms)\n[1/28] ProtocolHandlerTest.TokenMissing (9 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[20421:20421:0315/223624.591884:7731298034:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000560 with delay 0\n[20421:20421:0315/223624.591934:7731298084:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000560\n[20421:20421:0315/223624.591984:7731298134:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2408 with a delay 500000, Now = 210919424\n[20421:20421:0315/223624.592031:7731298180:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 500\n[20421:20421:0315/223624.592085:7731298233:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000540\n[20421:20421:0315/223624.592194:7731298342:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[20421:20421:0315/223624.592279:7731298434: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[20421:20421:0315/223624.592359:7731298508: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[20421:20421:0315/223624.592506:7731298658: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[20421:20421:0315/223624.592644:7731298803:ERROR:protocol-handler.cc(323)] Tried to send invalid message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true is_trickle_restart: true } } }\n[ OK ] ProtocolHandlerTest.InvalidOutboundMessage (1 ms)\n[2/28] ProtocolHandlerTest.InvalidOutboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[20421:20421:0315/223624.593165:7731299326:INFO:protocol-handler.cc(139)] Incoming message: { }\n[20421:20421:0315/223624.593225:7731299373:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[20421:20421:0315/223624.593267:7731299415:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[3/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[20421:20421:0315/223624.593573:7731299723:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -588068408 with a delay 10000, Now = 0\n[20421:20421:0315/223624.593614:7731299765:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003b0 with delay 10\n[20421:20421:0315/223624.593702:7731299851:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003b0\n[20421:20421:0315/223624.593742:7731299895:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[20421:20421:0315/223624.593792:7731299941:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 10000\n[20421:20421:0315/223624.593832:7731299980:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003c0 with delay 60\n[20421:20421:0315/223624.593888:7731300035:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7010000003c0\n[20421:20421:0315/223624.593922:7731300069:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[20421:20421:0315/223624.593955:7731300102:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 70000\n[20421:20421:0315/223624.593987:7731300134:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000003b0 with delay 60\n[20421:20421:0315/223624.594027:7731300174:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000003b0\n[20421:20421:0315/223624.594059:7731300206:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[20421:20421:0315/223624.594091:7731300238:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 130000\n[20421:20421:0315/223624.594123:7731300270:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7010000003c0 with delay 60\n[20421:20421:0315/223624.594156:7731300303:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7010000003c0\n[20421:20421:0315/223624.594187:7731300334:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[20421:20421:0315/223624.594219:7731300366:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 190000\n[20421:20421:0315/223624.594251:7731300398:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000003b0 with delay 60\n[20421:20421:0315/223624.594285:7731300432:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000003b0\n[20421:20421:0315/223624.594316:7731300463:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[20421:20421:0315/223624.594348:7731300495:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 250000\n[20421:20421:0315/223624.594380:7731300527:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7010000003c0 with delay 60\n[20421:20421:0315/223624.594413:7731300560:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7010000003c0\n[20421:20421:0315/223624.594444:7731300591:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[20421:20421:0315/223624.594475:7731300622:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 310000\n[20421:20421:0315/223624.594507:7731300656:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000003b0 with delay 60\n[20421:20421:0315/223624.594542:7731300689:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000003b0\n[20421:20421:0315/223624.594573:7731300720:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[20421:20421:0315/223624.594627:7731300775:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 370000\n[20421:20421:0315/223624.594668:7731300815:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7010000003c0 with delay 60\n[20421:20421:0315/223624.594705:7731300853:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7010000003c0\n[20421:20421:0315/223624.594740:7731300890:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (2 ms)\n[4/28] RecurringTaskTest.PeriodicTask (2 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[20421:20421:0315/223624.596017:7731302167:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -588068592 with a delay 10000, Now = 0\n[20421:20421:0315/223624.596059:7731302211:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003c0 with delay 10\n[20421:20421:0315/223624.596100:7731302251:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003c0\n[20421:20421:0315/223624.596143:7731302292:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[20421:20421:0315/223624.596188:7731302337:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 50000, Now = 10000\n[20421:20421:0315/223624.596231:7731302380:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003b0 with delay 50\n[20421:20421:0315/223624.596272:7731302420:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000003b0\n[20421:20421:0315/223624.596312:7731302461:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[20421:20421:0315/223624.596349:7731302499:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 149000, Now = 60000\n[20421:20421:0315/223624.596386:7731302537:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7010000003c0 with delay 149\n[20421:20421:0315/223624.596429:7731302577:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7010000003c0\n[20421:20421:0315/223624.596467:7731302615:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[20421:20421:0315/223624.596504:7731302655:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 248000, Now = 210000\n[20421:20421:0315/223624.596544:7731302692:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000003b0 with delay 248\n[20421:20421:0315/223624.596622:7731302771:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000003b0\n[20421:20421:0315/223624.596666:7731302817:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[20421:20421:0315/223624.596704:7731302852:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 446000, Now = 460000\n[20421:20421:0315/223624.596741:7731302889:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7010000003c0 with delay 446\n[20421:20421:0315/223624.596790:7731302938:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7010000003c0\n[20421:20421:0315/223624.596826:7731302975:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[20421:20421:0315/223624.596863:7731303011:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 842000, Now = 910000\n[20421:20421:0315/223624.596898:7731303073:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000003b0 with delay 842\n[20421:20421:0315/223624.596980:7731303127:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000003b0\n[20421:20421:0315/223624.597012:7731303163:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[20421:20421:0315/223624.597049:7731303197:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 1040000, Now = 1760000\n[20421:20421:0315/223624.597082:7731303229:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7010000003c0 with delay 1040\n[20421:20421:0315/223624.597137:7731303284:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7010000003c0\n[20421:20421:0315/223624.597169:7731303316:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[20421:20421:0315/223624.597205:7731303353:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 1040000, Now = 2800000\n[20421:20421:0315/223624.597238:7731303385:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000003b0 with delay 1040\n[20421:20421:0315/223624.597292:7731303440:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000003b0\n[20421:20421:0315/223624.597324:7731303471:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[5/28] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[20421:20421:0315/223624.598523:7731304673:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -588068552 with a delay 10000, Now = 0\n[20421:20421:0315/223624.598563:7731304715:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003b0 with delay 10\n[20421:20421:0315/223624.598635:7731304793:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003b0\n[20421:20421:0315/223624.598682:7731304838:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[20421:20421:0315/223624.598737:7731304886:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -588068552 with a delay 10000, Now = 10000\n[20421:20421:0315/223624.598786:7731304935:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003b0 with delay 10\n[20421:20421:0315/223624.598827:7731304976:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000003b0\n[20421:20421:0315/223624.598862:7731305012: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[20421:20421:0315/223624.600172:7731306321:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000003b0 with delay 920\n[20421:20421:0315/223624.600237:7731306385:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.600583:7731306731:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000003b0 with delay 45000\n[20421:20421:0315/223624.601657:7731307805:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000003b0\n[ OK ] ThrottleTest.ThrottlingScripted (1 ms)\n[7/28] ThrottleTest.ThrottlingScripted (1 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[20421:20421:0315/223624.601849:7731307999:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003b0 with delay 990\n[20421:20421:0315/223624.601942:7731308090:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.601982:7731308129:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.602047:7731308194:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.602081:7731308228:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.602140:7731308286:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.602173:7731308320:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.602232:7731308378:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.602265:7731308412:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.602324:7731308470:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.602362:7731308508:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.602421:7731308567:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.602454:7731308603:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7010000003c0 with delay 54000\n[20421:20421:0315/223624.604079:7731310227:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.604120:7731310267:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.604179:7731310326:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.604213:7731310359:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.604271:7731310417:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.604304:7731310451:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.604363:7731310509:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.604396:7731310542:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.604454:7731310601:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.604487:7731310634:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.604548:7731310695:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.604582:7731310729:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.604645:7731310799:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.604686:7731310833:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000003b0 with delay 54000\n[20421:20421:0315/223624.606261:7731312408:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.606298:7731312445:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.606357:7731312504:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.606391:7731312537:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.606449:7731312596:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.606482:7731312629:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.606543:7731312689:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.606576:7731312723:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.606634:7731312781:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.606676:7731312822:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.606734:7731312881:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.606767:7731312914:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.606826:7731312972:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.606858:7731313005:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7010000003c0 with delay 54000\n[20421:20421:0315/223624.608447:7731314595:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.608486:7731314633:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.608548:7731314695:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.608581:7731314728:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.608644:7731314798:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.608685:7731314832:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.608744:7731314890:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.608777:7731314924:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.608835:7731314982:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.608869:7731315015:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.608927:7731315073:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.608960:7731315107:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7010000003c0 with delay 1000\n[20421:20421:0315/223624.609023:7731315169:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7010000003c0\n[20421:20421:0315/223624.609055:7731315203:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000003b0 with delay 54000\n[20421:20421:0315/223624.610657:7731316804:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.610700:7731316847:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.610760:7731316907:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.610793:7731316940:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.610851:7731316998:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.610884:7731317031:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.610943:7731317089:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.610975:7731317122:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.611039:7731317185:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.611072:7731317219:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.611131:7731317277:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.611163:7731317310:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000003b0 with delay 1000\n[20421:20421:0315/223624.611222:7731317368:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000003b0\n[20421:20421:0315/223624.611254:7731317401:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7010000003c0 with delay 54000\n[20421:20421:0315/223624.612819:7731318966:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7010000003c0\n[ OK ] ThrottleTest.ThrottlingStorm (11 ms)\n[8/28] ThrottleTest.ThrottlingStorm (11 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[20419:20419:0315/223624.499521:7731205747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000640 with delay 0\n[20419:20419:0315/223624.500049:7731206207:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.500573:7731206724:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0\n[20419:20419:0315/223624.500670:7731206820:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000640\n[20419:20419:0315/223624.500755:7731206902:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820\n[20419:20419:0315/223624.500888:7731207042:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.500999:7731207149:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000870 with delay 0\n[20419:20419:0315/223624.501056:7731207203:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000870\n[20419:20419:0315/223624.501092:7731207242:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.501137:7731207286:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0\n[20419:20419:0315/223624.501179:7731207327:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820\n[20419:20419:0315/223624.501227:7731207377:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.501278:7731207428:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.501318:7731207471:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000870 with delay 0\n[20419:20419:0315/223624.501363:7731207510:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000870\n[20419:20419:0315/223624.501501:7731207651:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"5781642690264872593\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.501556:7731207706:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2504 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.501598:7731207747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 500\n[20419:20419:0315/223624.501640:7731207799:INFO:recurring-task.cc(55)] [Retry] Scheduling 2120 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.501692:7731207842:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007e0 with delay 60000\n[20419:20419:0315/223624.501747:7731207896:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820\n[20419:20419:0315/223624.501827:7731207981:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.502072:7731208222:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.502362:7731208512: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: \"5781642690264872593\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.502936:7731209088:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000820 with delay 0\n[20419:20419:0315/223624.502997:7731209146:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820\n[20419:20419:0315/223624.503167:7731209318:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"5781642690264872593\" 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[20419:20419:0315/223624.503250:7731209403:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"5781642690264872593\"\n[20419:20419:0315/223624.503297:7731209451:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.503348:7731209500:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.503395:7731209544:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000860 with delay 1200000\n[20419:20419:0315/223624.503443:7731209592:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.503730:7731209884:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.503782:7731209931:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 904 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.503826:7731209984:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000870 with delay 0\n[20419:20419:0315/223624.503956:7731210112: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[20419:20419:0315/223624.504020:7731210168:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000870\n[20419:20419:0315/223624.504153:7731210304:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 0\n[20419:20419:0315/223624.504215:7731210368:INFO:recurring-task.cc(55)] [Retry] Scheduling 904 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.504258:7731210407:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000640 with delay 10000\n[20419:20419:0315/223624.504300:7731210448:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000890\n[20419:20419:0315/223624.504335:7731210485:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (16 ms)\n[9/28] InvalidationClientImplTest.Start (16 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[20419:20419:0315/223624.505513:7731211665:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 0\n[20419:20419:0315/223624.505588:7731211738:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (0 ms)\n[10/28] InvalidationClientImplTest.GenerateNonce (0 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[20419:20419:0315/223624.506230:7731212381:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000850 with delay 0\n[20419:20419:0315/223624.506298:7731212447:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.506688:7731212839:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 0\n[20419:20419:0315/223624.506749:7731212899:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000850\n[20419:20419:0315/223624.506790:7731212938:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008b0\n[20419:20419:0315/223624.506873:7731213022:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.506939:7731213095:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0\n[20419:20419:0315/223624.506993:7731213141:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0\n[20419:20419:0315/223624.507028:7731213177:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.507077:7731213226:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 0\n[20419:20419:0315/223624.507119:7731213267:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008b0\n[20419:20419:0315/223624.507156:7731213305:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.507201:7731213351:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.507243:7731213393:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0\n[20419:20419:0315/223624.507282:7731213429:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0\n[20419:20419:0315/223624.507359:7731213510:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1293412296502030006\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.507405:7731213555:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2120 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.507454:7731213610:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 500\n[20419:20419:0315/223624.507504:7731213654:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.507546:7731213701:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 60000\n[20419:20419:0315/223624.507622:7731213771:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008b0\n[20419:20419:0315/223624.507673:7731213826:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.507732:7731213881:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.507898:7731214048: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: \"-1293412296502030006\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.508045:7731214195:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008b0 with delay 0\n[20419:20419:0315/223624.508089:7731214239:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008b0\n[20419:20419:0315/223624.508277:7731214427:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1293412296502030006\" 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[20419:20419:0315/223624.508358:7731214507:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1293412296502030006\"\n[20419:20419:0315/223624.508403:7731214552:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.508447:7731214598:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.508488:7731214641:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008e0 with delay 1200000\n[20419:20419:0315/223624.508535:7731214687:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.508688:7731214837:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.508740:7731214889:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.508779:7731214930:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0\n[20419:20419:0315/223624.508841:7731214996: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[20419:20419:0315/223624.508899:7731215048:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0\n[20419:20419:0315/223624.508977:7731215126:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 0\n[20419:20419:0315/223624.509027:7731215177:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.509068:7731215217:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000850 with delay 10000\n[20419:20419:0315/223624.509109:7731215256:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000910\n[20419:20419:0315/223624.509143:7731215292:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.509307:7731215457:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000910 with delay 0\n[20419:20419:0315/223624.509356:7731215505:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000910\n[20419:20419:0315/223624.509411:7731215561:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[20419:20419:0315/223624.509460:7731215608:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[20419:20419:0315/223624.509503:7731215651:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[20419:20419:0315/223624.509596:7731215754:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2120 with a delay 500000, Now = 211469424\n[20419:20419:0315/223624.509658:7731215811:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008f0 with delay 500\n[20419:20419:0315/223624.509704:7731215853:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2792 with a delay 60000000, Now = 211469424\n[20419:20419:0315/223624.509746:7731215895:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000900 with delay 60000\n[20419:20419:0315/223624.509810:7731215959:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008f0\n[20419:20419:0315/223624.509859:7731216032:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.509951:7731216101:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.509992:7731216142:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[20419:20419:0315/223624.510183:7731216332: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[20419:20419:0315/223624.510356:7731216508:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.510485:7731216651:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7010000008f0 with delay 0\n[20419:20419:0315/223624.510544:7731216723:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008f0\n[20419:20419:0315/223624.510901:7731217052: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[20419:20419:0315/223624.511052:7731217202: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[20419:20419:0315/223624.511165:7731217327:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[20419:20419:0315/223624.511320:7731217468:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[20419:20419:0315/223624.511415:7731217563:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[20419:20419:0315/223624.511720:7731217870:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000850\n[ OK ] InvalidationClientImplTest.Register (8 ms)\n[11/28] InvalidationClientImplTest.Register (8 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[20419:20419:0315/223624.513545:7731219696:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000790 with delay 0\n[20419:20419:0315/223624.513617:7731219766:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.514099:7731220250:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 0\n[20419:20419:0315/223624.514155:7731220305:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000790\n[20419:20419:0315/223624.514198:7731220345:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005f0\n[20419:20419:0315/223624.514282:7731220432:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.514352:7731220506:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000910 with delay 0\n[20419:20419:0315/223624.514406:7731220554:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000910\n[20419:20419:0315/223624.514441:7731220591:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.514484:7731220633:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 0\n[20419:20419:0315/223624.514531:7731220679:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005f0\n[20419:20419:0315/223624.514568:7731220717:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.514626:7731220809:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.514708:7731220857:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000910 with delay 0\n[20419:20419:0315/223624.514747:7731220895:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000910\n[20419:20419:0315/223624.514826:7731220979:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1588161771022843391\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.514885:7731221034:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.514926:7731221075:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 500\n[20419:20419:0315/223624.514967:7731221116:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.515028:7731221178:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000560 with delay 60000\n[20419:20419:0315/223624.515097:7731221247:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005f0\n[20419:20419:0315/223624.515138:7731221290:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.515193:7731221342:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.515349:7731221500: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: \"-1588161771022843391\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.515520:7731221669:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005f0 with delay 0\n[20419:20419:0315/223624.515566:7731221715:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005f0\n[20419:20419:0315/223624.515709:7731221859:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1588161771022843391\" 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[20419:20419:0315/223624.515803:7731221953:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1588161771022843391\"\n[20419:20419:0315/223624.515869:7731222018:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.515946:7731222096:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.515987:7731222170:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008b0 with delay 1200000\n[20419:20419:0315/223624.516070:7731222227:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.516221:7731222370:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.516268:7731222417:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1416 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.516312:7731222464:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 0\n[20419:20419:0315/223624.516378:7731222528: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[20419:20419:0315/223624.516431:7731222580:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000910\n[20419:20419:0315/223624.516508:7731222657:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000940 with delay 0\n[20419:20419:0315/223624.516560:7731222709:INFO:recurring-task.cc(55)] [Retry] Scheduling 1416 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.516601:7731222750:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000790 with delay 10000\n[20419:20419:0315/223624.516658:7731222806:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000940\n[20419:20419:0315/223624.516693:7731222843:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.516786:7731222936:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.516879:7731223029:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000940 with delay 0\n[20419:20419:0315/223624.516923:7731223073:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000940\n[20419:20419:0315/223624.517175:7731223324: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[20419:20419:0315/223624.517279:7731223429: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[20419:20419:0315/223624.517373:7731223522: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[20419:20419:0315/223624.517570:7731223719: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[20419:20419:0315/223624.517686:7731223834: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[20419:20419:0315/223624.517781:7731223934:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000940 with delay 0\n[20419:20419:0315/223624.517825:7731223974:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000910 with delay 0\n[20419:20419:0315/223624.517927:7731224076:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000920 with delay 0\n[20419:20419:0315/223624.517983:7731224133:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000940\n[20419:20419:0315/223624.518052:7731224202:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2984 with a delay 500000, Now = 211519424\n[20419:20419:0315/223624.518101:7731224250:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7010000005f0 with delay 500\n[20419:20419:0315/223624.518154:7731224302:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000910\n[20419:20419:0315/223624.518199:7731224346:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000920\n[20419:20419:0315/223624.518251:7731224400:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7010000005f0\n[20419:20419:0315/223624.518305:7731224455:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.518370:7731224527:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.518416:7731224573:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[20419:20419:0315/223624.518698:7731224849:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: \"2\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } }\n[ OK ] InvalidationClientImplTest.Invalidations (6 ms)\n[12/28] InvalidationClientImplTest.Invalidations (6 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[20419:20419:0315/223624.519636:7731225798:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000880 with delay 0\n[20419:20419:0315/223624.519720:7731225869:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.519986:7731226136:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0\n[20419:20419:0315/223624.520036:7731226186:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000880\n[20419:20419:0315/223624.520079:7731226227:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0\n[20419:20419:0315/223624.520154:7731226306:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.520223:7731226373:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0\n[20419:20419:0315/223624.520273:7731226421:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0\n[20419:20419:0315/223624.520309:7731226458:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.520356:7731226506:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0\n[20419:20419:0315/223624.520396:7731226544:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0\n[20419:20419:0315/223624.520437:7731226586:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.520480:7731226657:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.520548:7731226697:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0\n[20419:20419:0315/223624.520614:7731226762:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0\n[20419:20419:0315/223624.520703:7731226852:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4930591265906946617\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.520754:7731226904:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.520846:7731227000:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 500\n[20419:20419:0315/223624.520890:7731227048:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.520938:7731227094:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000710 with delay 60000\n[20419:20419:0315/223624.520996:7731227146:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0\n[20419:20419:0315/223624.521058:7731227207:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.521134:7731227287:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.521282:7731227434: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: \"4930591265906946617\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.521425:7731227575:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006e0 with delay 0\n[20419:20419:0315/223624.521467:7731227618:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0\n[20419:20419:0315/223624.521601:7731227751:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4930591265906946617\" 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[20419:20419:0315/223624.521675:7731227827:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4930591265906946617\"\n[20419:20419:0315/223624.521720:7731227869:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.521765:7731227914:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.521806:7731227955:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005c0 with delay 1200000\n[20419:20419:0315/223624.521851:7731228029:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.522035:7731228195:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.522090:7731228239:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.522135:7731228285:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0\n[20419:20419:0315/223624.522213:7731228387: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[20419:20419:0315/223624.522290:7731228438:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0\n[20419:20419:0315/223624.522370:7731228519:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005e0 with delay 0\n[20419:20419:0315/223624.522420:7731228570:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.522462:7731228612:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000880 with delay 10000\n[20419:20419:0315/223624.522500:7731228648:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005e0\n[20419:20419:0315/223624.522542:7731228694:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.522606:7731228755:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.522679:7731228831:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000005e0 with delay 0\n[20419:20419:0315/223624.522722:7731228873:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000005e0\n[20419:20419:0315/223624.522870:7731229026: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[20419:20419:0315/223624.522960:7731229110: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[20419:20419:0315/223624.523010:7731229165:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[20419:20419:0315/223624.523058:7731229207:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 3464 with a delay 500000, Now = 211469424\n[20419:20419:0315/223624.523099:7731229248:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008f0 with delay 500\n[20419:20419:0315/223624.523143:7731229292:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[20419:20419:0315/223624.523448:7731229602: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[20419:20419:0315/223624.523535:7731229685:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008f0\n[20419:20419:0315/223624.523580:7731229729:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.523705:7731229855:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.523750:7731229899:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[20419:20419:0315/223624.525782:7731231935: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[20419:20419:0315/223624.526181:7731232331:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000880\n[ OK ] InvalidationClientImplTest.ServerRequests (8 ms)\n[13/28] InvalidationClientImplTest.ServerRequests (8 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[20419:20419:0315/223624.527988:7731234140:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0\n[20419:20419:0315/223624.528063:7731234213:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.528343:7731234499:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0\n[20419:20419:0315/223624.528394:7731234548:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510\n[20419:20419:0315/223624.528445:7731234593:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0\n[20419:20419:0315/223624.528522:7731234672:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.528594:7731234744:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004a0 with delay 0\n[20419:20419:0315/223624.528644:7731234801:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004a0\n[20419:20419:0315/223624.528689:7731234839:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.528731:7731234881:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0\n[20419:20419:0315/223624.528773:7731234922:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0\n[20419:20419:0315/223624.528814:7731234963:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.528861:7731235014:INFO:recurring-task.cc(55)] [Startup] Scheduling 2984 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.528904:7731235056:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004a0 with delay 0\n[20419:20419:0315/223624.528946:7731235094:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004a0\n[20419:20419:0315/223624.529022:7731235172:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6829962264747171846\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.529073:7731235222:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2600 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.529116:7731235266:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 500\n[20419:20419:0315/223624.529159:7731235308:INFO:recurring-task.cc(55)] [Retry] Scheduling 2984 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.529200:7731235350:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 60000\n[20419:20419:0315/223624.529251:7731235405:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0\n[20419:20419:0315/223624.529296:7731235445:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.529354:7731235505:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.529500:7731235652: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: \"-6829962264747171846\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.529633:7731235794:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006e0 with delay 0\n[20419:20419:0315/223624.529690:7731235839:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0\n[20419:20419:0315/223624.529825:7731235975:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6829962264747171846\" 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[20419:20419:0315/223624.529927:7731236081:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6829962264747171846\"\n[20419:20419:0315/223624.529981:7731236134:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.530028:7731236178:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.530072:7731236221:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004f0 with delay 1200000\n[20419:20419:0315/223624.530118:7731236267:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.530264:7731236429:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.530322:7731236478:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.530370:7731236519:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004a0 with delay 0\n[20419:20419:0315/223624.530435:7731236585: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[20419:20419:0315/223624.530489:7731236638:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004a0\n[20419:20419:0315/223624.530570:7731236719:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003a0 with delay 0\n[20419:20419:0315/223624.530622:7731236771:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.530673:7731236822:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000510 with delay 10000\n[20419:20419:0315/223624.530711:7731236859:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003a0\n[20419:20419:0315/223624.530753:7731236903:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.530814:7731236967:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.530879:7731237032:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000003a0 with delay 0\n[20419:20419:0315/223624.530922:7731237074:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000003a0\n[20419:20419:0315/223624.531052:7731237202: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[20419:20419:0315/223624.531137:7731237286: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[20419:20419:0315/223624.531188:7731237337:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[20419:20419:0315/223624.531574:7731237724:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000510\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[14/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[20419:20419:0315/223624.533263:7731239415:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000760 with delay 0\n[20419:20419:0315/223624.533334:7731239484:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.533714:7731239866:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 0\n[20419:20419:0315/223624.533785:7731239935:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000760\n[20419:20419:0315/223624.533833:7731239980:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000840\n[20419:20419:0315/223624.533942:7731240091:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.534035:7731240185:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000920 with delay 0\n[20419:20419:0315/223624.534083:7731240232:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000920\n[20419:20419:0315/223624.534119:7731240273:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.534163:7731240325:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 0\n[20419:20419:0315/223624.534219:7731240368:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000840\n[20419:20419:0315/223624.534256:7731240405:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.534303:7731240452:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.534345:7731240497:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000920 with delay 0\n[20419:20419:0315/223624.534389:7731240537:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000920\n[20419:20419:0315/223624.534466:7731240616:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"5413994998061872273\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.534510:7731240663:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.534552:7731240704:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 500\n[20419:20419:0315/223624.534593:7731240742:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.534634:7731240794:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 60000\n[20419:20419:0315/223624.534698:7731240848:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000840\n[20419:20419:0315/223624.534778:7731240928:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.534857:7731241007:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.535013:7731241163: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: \"5413994998061872273\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.535155:7731241305:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000840 with delay 0\n[20419:20419:0315/223624.535200:7731241349:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000840\n[20419:20419:0315/223624.535334:7731241483:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"5413994998061872273\" 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[20419:20419:0315/223624.535399:7731241549:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"5413994998061872273\"\n[20419:20419:0315/223624.535443:7731241592:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.535488:7731241638:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.535539:7731241689:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 1200000\n[20419:20419:0315/223624.535585:7731241734:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.535749:7731241899:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.535798:7731241948:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.535844:7731241999:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000920 with delay 0\n[20419:20419:0315/223624.535915:7731242064: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[20419:20419:0315/223624.535966:7731242114:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000920\n[20419:20419:0315/223624.536045:7731242194:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000930 with delay 0\n[20419:20419:0315/223624.536093:7731242245:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.536135:7731242284:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000760 with delay 10000\n[20419:20419:0315/223624.536178:7731242325:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000930\n[20419:20419:0315/223624.536213:7731242368:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.536293:7731242442:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000930 with delay 0\n[20419:20419:0315/223624.536339:7731242489:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000930\n[20419:20419:0315/223624.536401:7731242550:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[20419:20419:0315/223624.536470:7731242619:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2984 with a delay 500000, Now = 211469424\n[20419:20419:0315/223624.536515:7731242664:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000920 with delay 500\n[20419:20419:0315/223624.536558:7731242708:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2120 with a delay 60000000, Now = 211469424\n[20419:20419:0315/223624.536599:7731242749:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000940 with delay 60000\n[20419:20419:0315/223624.536667:7731242816:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000920\n[20419:20419:0315/223624.536725:7731242874:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.536778:7731242939:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.536840:7731243033:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[20419:20419:0315/223624.537037:7731243193: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[20419:20419:0315/223624.537142:7731243291:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.537202:7731243351:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000920 with delay 0\n[20419:20419:0315/223624.537248:7731243397:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000920\n[20419:20419:0315/223624.537394:7731243544: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[20419:20419:0315/223624.537474:7731243624: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[20419:20419:0315/223624.537516:7731243703:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[20419:20419:0315/223624.537668:7731243818:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[20419:20419:0315/223624.538058:7731244208:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000760\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (7 ms)\n[15/28] InvalidationClientImplTest.IncomingAuthErrorMessage (7 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[20419:20419:0315/223624.539786:7731245939:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005e0 with delay 0\n[20419:20419:0315/223624.539868:7731246018:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.540136:7731246286:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0\n[20419:20419:0315/223624.540184:7731246334:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005e0\n[20419:20419:0315/223624.540228:7731246376:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510\n[20419:20419:0315/223624.540301:7731246454:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.540373:7731246523:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007f0 with delay 0\n[20419:20419:0315/223624.540431:7731246578:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007f0\n[20419:20419:0315/223624.540466:7731246616:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.540510:7731246660:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0\n[20419:20419:0315/223624.540550:7731246706:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510\n[20419:20419:0315/223624.540602:7731246762:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.540677:7731246828:INFO:recurring-task.cc(55)] [Startup] Scheduling 2888 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.540721:7731246872:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007f0 with delay 0\n[20419:20419:0315/223624.540764:7731246913:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007f0\n[20419:20419:0315/223624.540843:7731246999:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-8198242419052302964\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.540897:7731247046:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2696 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.540938:7731247088:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 500\n[20419:20419:0315/223624.540977:7731247129:INFO:recurring-task.cc(55)] [Retry] Scheduling 2888 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.541018:7731247170:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000610 with delay 60000\n[20419:20419:0315/223624.541071:7731247221:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510\n[20419:20419:0315/223624.541114:7731247263:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.541172:7731247334:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.541336:7731247489: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: \"-8198242419052302964\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.541478:7731247627:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000510 with delay 0\n[20419:20419:0315/223624.541520:7731247672:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510\n[20419:20419:0315/223624.541664:7731247815:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-8198242419052302964\" 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[20419:20419:0315/223624.541727:7731247876:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-8198242419052302964\"\n[20419:20419:0315/223624.541775:7731247925:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.541821:7731247970:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.541893:7731248047:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008b0 with delay 1200000\n[20419:20419:0315/223624.541948:7731248097:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.542086:7731248236:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.542141:7731248290:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.542190:7731248339:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007f0 with delay 0\n[20419:20419:0315/223624.542256:7731248409: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[20419:20419:0315/223624.542312:7731248461:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000007f0\n[20419:20419:0315/223624.542390:7731248540:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000410 with delay 0\n[20419:20419:0315/223624.542441:7731248591:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.542483:7731248633:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005e0 with delay 10000\n[20419:20419:0315/223624.542522:7731248669:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000410\n[20419:20419:0315/223624.542557:7731248710:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.542620:7731248770:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000410 with delay 0\n[20419:20419:0315/223624.542674:7731248824:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000410\n[20419:20419:0315/223624.542732:7731248882:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[20419:20419:0315/223624.542801:7731248953:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2696 with a delay 500000, Now = 211469424\n[20419:20419:0315/223624.542848:7731249005:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000007f0 with delay 500\n[20419:20419:0315/223624.542897:7731249046:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2504 with a delay 60000000, Now = 211469424\n[20419:20419:0315/223624.542938:7731249088:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000004b0 with delay 60000\n[20419:20419:0315/223624.542997:7731249146:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000007f0\n[20419:20419:0315/223624.543043:7731249192:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.543110:7731249265:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.543165:7731249319:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[20419:20419:0315/223624.543357:7731249507: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[20419:20419:0315/223624.543689:7731249839:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000005e0\n[20419:20419:0315/223624.544844:7731250996:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000610\n[20419:20419:0315/223624.544899:7731251046:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7010000004b0\n[20419:20419:0315/223624.544960:7731251114: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[20419:20419:0315/223624.545005:7731251156:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[20419:20419:0315/223624.545097:7731251248: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[20419:20419:0315/223624.545151:7731251300:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2696 with a delay 500000, Now = 271469424\n[20419:20419:0315/223624.545194:7731251343:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000610 with delay 500\n[20419:20419:0315/223624.545236:7731251386:INFO:recurring-task.cc(55)] [Retry] Scheduling 2504 with a delay 60000000, Now = 271469424\n[20419:20419:0315/223624.545284:7731251433:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7010000005e0 with delay 60000\n[20419:20419:0315/223624.545338:7731251487:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000610\n[20419:20419:0315/223624.545382:7731251532:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.545442:7731251591:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.545483:7731251632:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[20419:20419:0315/223624.545663:7731251814:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 1 registration_digest: \"\\327\\003\\047\\242\\324@\\3740-O\\354\\3229\\352\\000\\231\\340\\204\\224\\323\" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: \"3\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } server_registration_summary_requested: true } }\n[ OK ] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[16/28] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[20419:20419:0315/223624.547713:7731253865:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 0\n[20419:20419:0315/223624.547788:7731253938:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.548032:7731254186:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 0\n[20419:20419:0315/223624.548081:7731254233:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000800\n[20419:20419:0315/223624.548123:7731254271:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004d0\n[20419:20419:0315/223624.548199:7731254349:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.548266:7731254417:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[20419:20419:0315/223624.548319:7731254467:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[20419:20419:0315/223624.548357:7731254508:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.548405:7731254555:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 0\n[20419:20419:0315/223624.548450:7731254598:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004d0\n[20419:20419:0315/223624.548486:7731254636:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.548528:7731254680:INFO:recurring-task.cc(55)] [Startup] Scheduling 3464 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.548571:7731254723:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[20419:20419:0315/223624.548613:7731254761:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[20419:20419:0315/223624.548701:7731254851:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2937316866299318971\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.548754:7731254903:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3080 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.548795:7731254945:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 500\n[20419:20419:0315/223624.548838:7731254987:INFO:recurring-task.cc(55)] [Retry] Scheduling 3464 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.548888:7731255037:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007a0 with delay 60000\n[20419:20419:0315/223624.548939:7731255092:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004d0\n[20419:20419:0315/223624.548983:7731255132:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.549039:7731255189:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.549213:7731255365: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: \"-2937316866299318971\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.549347:7731255499:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004d0 with delay 0\n[20419:20419:0315/223624.549400:7731255549:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004d0\n[20419:20419:0315/223624.549540:7731255689:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2937316866299318971\" 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[20419:20419:0315/223624.549604:7731255758:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2937316866299318971\"\n[20419:20419:0315/223624.549659:7731255811:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.549705:7731255855:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.549747:7731255897:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007f0 with delay 1200000\n[20419:20419:0315/223624.549793:7731255942:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.549967:7731256119:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.550016:7731256167:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.550057:7731256206:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0\n[20419:20419:0315/223624.550122:7731256275: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[20419:20419:0315/223624.550179:7731256327:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0\n[20419:20419:0315/223624.550258:7731256408:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000410 with delay 0\n[20419:20419:0315/223624.550309:7731256472:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.550378:7731256528:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000800 with delay 10000\n[20419:20419:0315/223624.550424:7731256572:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000410\n[20419:20419:0315/223624.550463:7731256612:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.550528:7731256678:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.550582:7731256736:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000410 with delay 0\n[20419:20419:0315/223624.550626:7731256775:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000410\n[20419:20419:0315/223624.550740:7731256892: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[20419:20419:0315/223624.551028:7731257178:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000800\n[20419:20419:0315/223624.552055:7731258205: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 (5 ms)\n[17/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[20419:20419:0315/223624.552838:7731258995:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000660 with delay 0\n[20419:20419:0315/223624.552917:7731259066:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[20419:20419:0315/223624.553160:7731259317:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000530 with delay 0\n[20419:20419:0315/223624.553211:7731259360:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000660\n[20419:20419:0315/223624.553257:7731259404:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000530\n[20419:20419:0315/223624.553332:7731259482:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[20419:20419:0315/223624.553401:7731259551:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[20419:20419:0315/223624.553451:7731259599:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[20419:20419:0315/223624.553486:7731259636:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[20419:20419:0315/223624.553529:7731259679:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000530 with delay 0\n[20419:20419:0315/223624.553573:7731259721:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000530\n[20419:20419:0315/223624.553609:7731259758:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[20419:20419:0315/223624.553661:7731259813:INFO:recurring-task.cc(55)] [Startup] Scheduling 2792 with a delay 0, Now = 210919424\n[20419:20419:0315/223624.553704:7731259857:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[20419:20419:0315/223624.553746:7731259894:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[20419:20419:0315/223624.553823:7731259972:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2344722571060724564\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[20419:20419:0315/223624.553903:7731260054:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424\n[20419:20419:0315/223624.553950:7731260099:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000530 with delay 500\n[20419:20419:0315/223624.553997:7731260147:INFO:recurring-task.cc(55)] [Retry] Scheduling 2792 with a delay 60000000, Now = 210919424\n[20419:20419:0315/223624.554037:7731260189:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 60000\n[20419:20419:0315/223624.554091:7731260243:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000530\n[20419:20419:0315/223624.554133:7731260283:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.554194:7731260344:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[20419:20419:0315/223624.554346:7731260501: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: \"2344722571060724564\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[20419:20419:0315/223624.554480:7731260630:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000530 with delay 0\n[20419:20419:0315/223624.554527:7731260677:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000530\n[20419:20419:0315/223624.554672:7731260822:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2344722571060724564\" 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[20419:20419:0315/223624.554779:7731260932:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2344722571060724564\"\n[20419:20419:0315/223624.554824:7731260974:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[20419:20419:0315/223624.554876:7731261026:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[20419:20419:0315/223624.554917:7731261066:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000410 with delay 1200000\n[20419:20419:0315/223624.554962:7731261112:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[20419:20419:0315/223624.555105:7731261257:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.555149:7731261298:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[20419:20419:0315/223624.555191:7731261340:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0\n[20419:20419:0315/223624.555251:7731261403: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[20419:20419:0315/223624.555307:7731261455:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0\n[20419:20419:0315/223624.555385:7731261535:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004d0 with delay 0\n[20419:20419:0315/223624.555436:7731261586:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[20419:20419:0315/223624.555478:7731261628:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000660 with delay 10000\n[20419:20419:0315/223624.555517:7731261665:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004d0\n[20419:20419:0315/223624.555552:7731261704:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[20419:20419:0315/223624.555848:7731262002:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000660\n[20419:20419:0315/223624.557020:7731263168:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000480\n[20419:20419:0315/223624.584416:7731290567:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000410\n[20419:20419:0315/223624.584506:7731290662:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.584585:7731290734:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[20419:20419:0315/223624.584638:7731290795:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[20419:20419:0315/223624.584879:7731291029: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[20419:20419:0315/223624.584931:7731291081:INFO:recurring-task.cc(55)] [Send-info] Scheduling 3464 with a delay 500000, Now = 1411419424\n[20419:20419:0315/223624.584984:7731291134:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000480 with delay 500\n[20419:20419:0315/223624.585033:7731291183:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[20419:20419:0315/223624.585076:7731291225:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000660 with delay 1200000\n[20419:20419:0315/223624.585126:7731291274:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000480\n[20419:20419:0315/223624.585184:7731291333:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.585331:7731291481:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[20419:20419:0315/223624.585386:7731291536:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[20419:20419:0315/223624.585662:7731291813: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 (35 ms)\n[18/28] InvalidationClientImplTest.Heartbeats (35 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[20420:20420:0315/223624.563441:7731269699:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 0\n[20420:20420:0315/223624.564209:7731270373:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000540\n[20420:20420:0315/223624.564617:7731270768: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[20420:20420:0315/223624.564702:7731270852:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 500000, Now = 210919424\n[20420:20420:0315/223624.564758:7731270908:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005e0 with delay 500\n[20420:20420:0315/223624.564830:7731270986:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005e0\n[20420:20420:0315/223624.565186:7731271345: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 (8 ms)\n[19/28] ProtocolHandlerTest.SendInitializeOnly (8 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[20420:20420:0315/223624.566924:7731273076:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"fake nonce\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } token_control_message: { new_token: \"new token\" } }\n[ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[20/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[20420:20420:0315/223624.567509:7731273659:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 0\n[20420:20420:0315/223624.567678:7731273828:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000500 with delay 0\n[20420:20420:0315/223624.567743:7731273898:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 0\n[20420:20420:0315/223624.567824:7731273981:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004c0 with delay 0\n[20420:20420:0315/223624.567875:7731274022:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000470 with delay 0\n[20420:20420:0315/223624.567925:7731274087:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[20420:20420:0315/223624.568499:7731274654:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004d0\n[20420:20420:0315/223624.568644:7731274809: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[20420:20420:0315/223624.568736:7731274885:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2408 with a delay 500000, Now = 210919424\n[20420:20420:0315/223624.568798:7731274953:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000630 with delay 500\n[20420:20420:0315/223624.568857:7731275005:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000500\n[20420:20420:0315/223624.568904:7731275051:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000480\n[20420:20420:0315/223624.568940:7731275086:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004c0\n[20420:20420:0315/223624.568984:7731275131:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000470\n[20420:20420:0315/223624.569022:7731275169:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[20420:20420:0315/223624.569098:7731275257:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[20420:20420:0315/223624.569200:7731275378:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000630\n[20420:20420:0315/223624.569420:7731275575:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[20420:20420:0315/223624.577509:7731283668: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 (11 ms)\n[21/28] ProtocolHandlerTest.SendMultipleMessageTypes (11 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[20420:20420:0315/223624.579808:7731285959:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } invalidation_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[22/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[20420:20420:0315/223624.580557:7731286719: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[20420:20420:0315/223624.580678:7731286828: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[20420:20420:0315/223624.580784:7731286933: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[20420:20420:0315/223624.580906:7731287056:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[23/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[20420:20420:0315/223624.581442:7731287592: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[20420:20420:0315/223624.581581:7731287731: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[24/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[20420:20420:0315/223624.582140:7731288290: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[25/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[20420:20420:0315/223624.582715:7731288872: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[20420:20420:0315/223624.582791:7731288941:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000400 with delay 0\n[20420:20420:0315/223624.582839:7731288991:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000400\n[20420:20420:0315/223624.582935:7731289090: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[20420:20420:0315/223624.583005:7731289159:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2792 with a delay 500000, Now = 210919424\n[20420:20420:0315/223624.583053:7731289209:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000410 with delay 500\n[20420:20420:0315/223624.583111:7731289263:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000410\n[20420:20420:0315/223624.583164:7731289313:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (44 ms)\n[26/28] ProtocolHandlerTest.ConfigMessage (44 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[20420:20420:0315/223624.627790:7731333956:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.ErrorMessage (1 ms)\n[27/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[20420:20420:0315/223624.628868:7731335031: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[28/28] ProtocolHandlerTest.TokenMismatch (1 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "8985404d7efc518c5d41e117c9db12f835380bb7", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "439dd1bf53f48311", "server_versions": [ "4201-b04f7f8" ], "started_ts": "2019-03-16T05:36:18.146548", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux ChromiumOS MSan Tests", "buildnumber:11842", "cpu:x86-64", "data:26eb11a34f57da9a2abf246039845ba8f72fdd47", "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:swarm2374-c4", "spec_name:chromium.ci:Linux ChromiumOS MSan Tests", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:84dc2e055f380db17943d027893da36f2780b31c", "user:None" ], "task_id": "43a37897cd4de310" } ] }