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-5kwc" ] }, { "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": [ "3945-402d3be" ] }, { "key": "zone", "value": [ "us", "us-east", "us-east1", "us-east1-b" ] } ], "bot_id": "gce-trusty-e833d7b0-us-east1-b-5kwc", "bot_version": "14fa84c24d76966aabd6df511c4f24bad7f85c257fbfc5598ebc215b5d8f9e97", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "a2dqpK39PjGpFdcdw62OAE0JOJJ9n8J_AXpJHmH0QCIC" }, "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-01-08T16:47:58.997456", "cost_saved_usd": 0.0009636131315612939, "created_ts": "2019-01-09T00:58:49.266752", "deduped_from": "42472e7c530e1011", "duration": 1.0249810218811035, "modified_ts": "2019-01-09T00:58:49.284590", "name": "cacheinvalidation_unittests (with patch)/Ubuntu-14.04/049a506d6c/linux_chromium_msan_rel_ng/1336", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n MSAN_OPTIONS=symbolize=0\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioPm480f/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.SendInitializeOnly\n[24854:24854:0108/084757.343662:33218211385:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002000 with delay 0\n[24854:24854:0108/084757.343976:33218211700:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002000\n[24854:24854:0108/084757.344376:33218212097: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[24854:24854:0108/084757.344456:33218212174:INFO:recurring-task.cc(55)] [Startup] Scheduling 9320 with a delay 500000, Now = 210919424\n[24854:24854:0108/084757.344513:33218212238:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001fe0 with delay 500\n[24854:24854:0108/084757.344582:33218212305:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001fe0\n[24854:24854:0108/084757.344868:33218212586:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } initialize_message: { client_type: 2 nonce: \"unit-test-nonce\" application_client_id: { client_type: 2 client_name: \"unit-test-client-id\" } digest_serialization_type: BYTE_BASED } }\n[ OK ] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[1/28] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[24854:24854:0108/084757.346118:33218213847: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[2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[24854:24854:0108/084757.346643:33218214381:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000020b0 with delay 0\n[24854:24854:0108/084757.346743:33218214470:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002050 with delay 0\n[24854:24854:0108/084757.346797:33218214516:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000020d0 with delay 0\n[24854:24854:0108/084757.346914:33218214639:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002090 with delay 0\n[24854:24854:0108/084757.346963:33218214679:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000020e0 with delay 0\n[24854:24854:0108/084757.347006:33218214733:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000020a0 with delay 0\n[24854:24854:0108/084757.347397:33218215121:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000020b0\n[24854:24854:0108/084757.347557:33218215296: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[24854:24854:0108/084757.347654:33218215372:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424\n[24854:24854:0108/084757.347714:33218215439:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002000 with delay 500\n[24854:24854:0108/084757.347780:33218215498:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002050\n[24854:24854:0108/084757.347827:33218215543:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000020d0\n[24854:24854:0108/084757.347865:33218215580:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002090\n[24854:24854:0108/084757.347903:33218215619:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000020e0\n[24854:24854:0108/084757.347939:33218215655:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000020a0\n[24854:24854:0108/084757.347998:33218215718:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[24854:24854:0108/084757.348061:33218215785:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002000\n[24854:24854:0108/084757.348242:33218215963:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[24854:24854:0108/084757.348647:33218216371:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } registration_message: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } registration: { object_id: { source: 2 name: \"oid1\" } op_type: UNREGISTER } registration: { object_id: { source: 2 name: \"oid2\" } op_type: UNREGISTER } } registration_sync_message: { subtree: { registered_object: { source: 2 name: \"oid0\" } } } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"unit-test\" } performance_counter: { name: \"x\" value: 3 } performance_counter: { name: \"y\" value: 81 } server_registration_summary_requested: true } }\n[ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms)\n[3/28] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[24854:24854:0108/084757.350499:33218218227: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[4/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[24854:24854:0108/084757.351169:33218218896: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[24854:24854:0108/084757.351267:33218218985: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[24854:24854:0108/084757.351369:33218219091: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[24854:24854:0108/084757.351520:33218219255: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[5/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[24854:24854:0108/084757.352097:33218219816: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[24854:24854:0108/084757.352229:33218219946:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[6/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[24854:24854:0108/084757.352788:33218220507:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.MinorVersionMismatch (0 ms)\n[7/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[24854:24854:0108/084757.353312:33218221031: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[24854:24854:0108/084757.353378:33218221097:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002040 with delay 0\n[24854:24854:0108/084757.353420:33218221150:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002040\n[24854:24854:0108/084757.353535:33218221253: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[24854:24854:0108/084757.353616:33218221341:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424\n[24854:24854:0108/084757.353673:33218221396:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002170 with delay 500\n[24854:24854:0108/084757.353731:33218221450:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002170\n[24854:24854:0108/084757.353784:33218221503:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (7 ms)\n[8/28] ProtocolHandlerTest.ConfigMessage (7 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[24854:24854:0108/084757.360918:33218228638: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[9/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[24854:24854:0108/084757.361473:33218229191:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.TokenMismatch (0 ms)\n[10/28] ProtocolHandlerTest.TokenMismatch (0 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[24851:24851:0108/084757.302679:33218170404:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ef0 with delay 0\n[24851:24851:0108/084757.303024:33218170748:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.303368:33218171086:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d90 with delay 0\n[24851:24851:0108/084757.303433:33218171164:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001ef0\n[24851:24851:0108/084757.303495:33218171211:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d90\n[24851:24851:0108/084757.303594:33218171311:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.303758:33218171479:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d30 with delay 0\n[24851:24851:0108/084757.303809:33218171525:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d30\n[24851:24851:0108/084757.303845:33218171566:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.303894:33218171623:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d90 with delay 0\n[24851:24851:0108/084757.303948:33218171664:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d90\n[24851:24851:0108/084757.303993:33218171710:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.304042:33218171758:INFO:recurring-task.cc(55)] [Startup] Scheduling 9320 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.304103:33218171820:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d30 with delay 0\n[24851:24851:0108/084757.304166:33218171883:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d30\n[24851:24851:0108/084757.304272:33218171989:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4684553336949134117\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.304366:33218172089:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.304419:33218172143:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d90 with delay 500\n[24851:24851:0108/084757.304467:33218172188:INFO:recurring-task.cc(55)] [Retry] Scheduling 9320 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.304535:33218172268:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d60 with delay 60000\n[24851:24851:0108/084757.304607:33218172324:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d90\n[24851:24851:0108/084757.304666:33218172384:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.304743:33218172465:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.304960:33218172678: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: \"4684553336949134117\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.305159:33218172878:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d90 with delay 0\n[24851:24851:0108/084757.305214:33218172936:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d90\n[24851:24851:0108/084757.305442:33218173159:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4684553336949134117\" 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[24851:24851:0108/084757.305526:33218173247:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4684553336949134117\"\n[24851:24851:0108/084757.305608:33218173334:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.305672:33218173431:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.305793:33218173518:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d30 with delay 1200000\n[24851:24851:0108/084757.305848:33218173565:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.306070:33218173788:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.306118:33218173839:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.306182:33218173899:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ef0 with delay 0\n[24851:24851:0108/084757.306279:33218173999: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[24851:24851:0108/084757.306348:33218174065:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001ef0\n[24851:24851:0108/084757.306452:33218174169:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ce0 with delay 0\n[24851:24851:0108/084757.306509:33218174235:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.306566:33218174295:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d20 with delay 10000\n[24851:24851:0108/084757.306647:33218174368:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001ce0\n[24851:24851:0108/084757.306688:33218174411:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (6 ms)\n[11/28] InvalidationClientImplTest.Start (6 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[24851:24851:0108/084757.307542:33218175261:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d70 with delay 0\n[24851:24851:0108/084757.307623:33218175341:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (0 ms)\n[12/28] InvalidationClientImplTest.GenerateNonce (0 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[24851:24851:0108/084757.308186:33218175904:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.308247:33218175963:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.308608:33218176327:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c90 with delay 0\n[24851:24851:0108/084757.308724:33218176441:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001da0\n[24851:24851:0108/084757.308765:33218176480:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c90\n[24851:24851:0108/084757.308838:33218176557:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.308910:33218176639:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001cb0 with delay 0\n[24851:24851:0108/084757.308974:33218176690:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001cb0\n[24851:24851:0108/084757.309010:33218176727:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.309055:33218176776:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c90 with delay 0\n[24851:24851:0108/084757.309100:33218176816:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c90\n[24851:24851:0108/084757.309136:33218176858:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.309201:33218176922:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.309260:33218176978:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001cb0 with delay 0\n[24851:24851:0108/084757.309305:33218177020:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001cb0\n[24851:24851:0108/084757.309384:33218177101:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2114170308474936204\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.309452:33218177169:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9320 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.309492:33218177209:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c90 with delay 500\n[24851:24851:0108/084757.309529:33218177249:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.309568:33218177300:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001cc0 with delay 60000\n[24851:24851:0108/084757.309624:33218177351:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c90\n[24851:24851:0108/084757.309687:33218177409:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.309803:33218177527:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.309965:33218177683: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: \"-2114170308474936204\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.310122:33218177841:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c90 with delay 0\n[24851:24851:0108/084757.310169:33218177900:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c90\n[24851:24851:0108/084757.310343:33218178061:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2114170308474936204\" 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[24851:24851:0108/084757.310447:33218178165:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2114170308474936204\"\n[24851:24851:0108/084757.310498:33218178221:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.310557:33218178285:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.310617:33218178335:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001cb0 with delay 1200000\n[24851:24851:0108/084757.310679:33218178397:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.310821:33218178539:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.310871:33218178588:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.310910:33218178641:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.310986:33218178706: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[24851:24851:0108/084757.311045:33218178762:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001da0\n[24851:24851:0108/084757.311123:33218178840:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.311174:33218178890:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.311211:33218178930:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c80 with delay 10000\n[24851:24851:0108/084757.311249:33218178965:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c70\n[24851:24851:0108/084757.311283:33218179010:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.311395:33218179119:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.311442:33218179159:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001c70\n[24851:24851:0108/084757.311496:33218179213:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[24851:24851:0108/084757.311556:33218179272:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[24851:24851:0108/084757.311611:33218179327:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[24851:24851:0108/084757.311705:33218179423:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9320 with a delay 500000, Now = 211469424\n[24851:24851:0108/084757.311747:33218179465:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001da0 with delay 500\n[24851:24851:0108/084757.311794:33218179516:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424\n[24851:24851:0108/084757.311846:33218179566:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c90 with delay 60000\n[24851:24851:0108/084757.311900:33218179617:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001da0\n[24851:24851:0108/084757.311939:33218179658:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.311997:33218179714:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.312038:33218179755:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[24851:24851:0108/084757.312219:33218179936: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[24851:24851:0108/084757.312338:33218180058:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.312438:33218180156:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.312478:33218180204:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001da0\n[24851:24851:0108/084757.312776:33218180498: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[24851:24851:0108/084757.312901:33218180626: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[24851:24851:0108/084757.313018:33218180741:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[24851:24851:0108/084757.313180:33218180897:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[24851:24851:0108/084757.313270:33218180986:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[24851:24851:0108/084757.313382:33218181100:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001c80\n[ OK ] InvalidationClientImplTest.Register (6 ms)\n[13/28] InvalidationClientImplTest.Register (6 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[24851:24851:0108/084757.314364:33218182085:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e20 with delay 0\n[24851:24851:0108/084757.314433:33218182150:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.314810:33218182582:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ea0 with delay 0\n[24851:24851:0108/084757.314912:33218182636:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001e20\n[24851:24851:0108/084757.314962:33218182678:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001ea0\n[24851:24851:0108/084757.315035:33218182754:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.315100:33218182818:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c80 with delay 0\n[24851:24851:0108/084757.315147:33218182866:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c80\n[24851:24851:0108/084757.315185:33218182902:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.315232:33218182950:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ea0 with delay 0\n[24851:24851:0108/084757.315272:33218182988:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001ea0\n[24851:24851:0108/084757.315307:33218183024:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.315347:33218183075:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.315395:33218183115:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c80 with delay 0\n[24851:24851:0108/084757.315435:33218183151:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c80\n[24851:24851:0108/084757.315507:33218183230:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6350194915251945177\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.315586:33218183303:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.315629:33218183351:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ea0 with delay 500\n[24851:24851:0108/084757.315684:33218183401:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.315730:33218183447:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000020e0 with delay 60000\n[24851:24851:0108/084757.315771:33218183491:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001ea0\n[24851:24851:0108/084757.315812:33218183529:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.315867:33218183587:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.316011:33218183736: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: \"-6350194915251945177\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.316170:33218183892:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ea0 with delay 0\n[24851:24851:0108/084757.316222:33218183941:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001ea0\n[24851:24851:0108/084757.316383:33218184105:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6350194915251945177\" 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[24851:24851:0108/084757.316465:33218184184:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6350194915251945177\"\n[24851:24851:0108/084757.316510:33218184228:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.316561:33218184288:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.316615:33218184332:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c80 with delay 1200000\n[24851:24851:0108/084757.316668:33218184384:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.316801:33218184521:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.316852:33218184573:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1928 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.316919:33218184639:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001e20 with delay 0\n[24851:24851:0108/084757.316981:33218184698: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[24851:24851:0108/084757.317032:33218184749:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001e20\n[24851:24851:0108/084757.317116:33218184834:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.317170:33218184887:INFO:recurring-task.cc(55)] [Retry] Scheduling 1928 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.317214:33218184931:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001da0 with delay 10000\n[24851:24851:0108/084757.317251:33218184966:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c70\n[24851:24851:0108/084757.317287:33218185004:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.317351:33218185068:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.317422:33218185140:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.317465:33218185182:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001c70\n[24851:24851:0108/084757.317702:33218185422: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[24851:24851:0108/084757.317809:33218185526: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[24851:24851:0108/084757.317896:33218185613: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[24851:24851:0108/084757.318043:33218185760: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[24851:24851:0108/084757.318140:33218185859: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[24851:24851:0108/084757.318230:33218185951:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.318272:33218185995:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001e20 with delay 0\n[24851:24851:0108/084757.318322:33218186040:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001ea0 with delay 0\n[24851:24851:0108/084757.318362:33218186079:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000001c70\n[24851:24851:0108/084757.318418:33218186136:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424\n[24851:24851:0108/084757.318467:33218186184:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001c60 with delay 500\n[24851:24851:0108/084757.318510:33218186226:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000001e20\n[24851:24851:0108/084757.318552:33218186267:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000001ea0\n[24851:24851:0108/084757.318606:33218186323:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000001c60\n[24851:24851:0108/084757.318663:33218186386:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.318729:33218186450:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.318771:33218186497:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[24851:24851:0108/084757.318984:33218186702:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: \"2\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } }\n[ OK ] InvalidationClientImplTest.Invalidations (5 ms)\n[14/28] InvalidationClientImplTest.Invalidations (5 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[24851:24851:0108/084757.319868:33218187588:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ef0 with delay 0\n[24851:24851:0108/084757.319936:33218187653:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.320186:33218187907:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001f10 with delay 0\n[24851:24851:0108/084757.320235:33218187953:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001ef0\n[24851:24851:0108/084757.320275:33218187991:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001f10\n[24851:24851:0108/084757.320369:33218188094:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.320453:33218188171:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001fc0 with delay 0\n[24851:24851:0108/084757.320504:33218188220:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001fc0\n[24851:24851:0108/084757.320539:33218188256:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.320589:33218188306:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001f10 with delay 0\n[24851:24851:0108/084757.320627:33218188343:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001f10\n[24851:24851:0108/084757.320671:33218188394:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.320722:33218188442:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.320763:33218188485:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001fc0 with delay 0\n[24851:24851:0108/084757.320813:33218188530:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001fc0\n[24851:24851:0108/084757.320890:33218188614:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-4674211671458290705\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.320950:33218188667:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.320990:33218188714:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001f10 with delay 500\n[24851:24851:0108/084757.321040:33218188757:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.321077:33218188796:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e90 with delay 60000\n[24851:24851:0108/084757.321117:33218188849:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001f10\n[24851:24851:0108/084757.321182:33218188899:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.321236:33218188960:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.321386:33218189113: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: \"-4674211671458290705\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.321538:33218189258:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001f10 with delay 0\n[24851:24851:0108/084757.321591:33218189309:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001f10\n[24851:24851:0108/084757.321734:33218189455:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-4674211671458290705\" 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[24851:24851:0108/084757.321807:33218189525:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-4674211671458290705\"\n[24851:24851:0108/084757.321852:33218189574:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.321904:33218189621:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.321948:33218189666:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001fc0 with delay 1200000\n[24851:24851:0108/084757.321994:33218189712:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.322188:33218189909:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.322233:33218189950:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.322275:33218189992:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ef0 with delay 0\n[24851:24851:0108/084757.322337:33218190056: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[24851:24851:0108/084757.322389:33218190104:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001ef0\n[24851:24851:0108/084757.322461:33218190179:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002170 with delay 0\n[24851:24851:0108/084757.322508:33218190225:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.322552:33218190270:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001400 with delay 10000\n[24851:24851:0108/084757.322600:33218190316:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002170\n[24851:24851:0108/084757.322634:33218190363:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.322702:33218190420:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.322762:33218190481:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000002170 with delay 0\n[24851:24851:0108/084757.322801:33218190529:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000002170\n[24851:24851:0108/084757.322964:33218190684: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[24851:24851:0108/084757.323059:33218190781: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[24851:24851:0108/084757.323109:33218190828:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[24851:24851:0108/084757.323158:33218190877:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424\n[24851:24851:0108/084757.323205:33218190922:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001ef0 with delay 500\n[24851:24851:0108/084757.323247:33218190964:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[24851:24851:0108/084757.323534:33218191255: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[24851:24851:0108/084757.323617:33218191334:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001ef0\n[24851:24851:0108/084757.323664:33218191381:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.323746:33218191470:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.323799:33218191517:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[24851:24851:0108/084757.324103:33218191833: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[24851:24851:0108/084757.324285:33218192024:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001400\n[ OK ] InvalidationClientImplTest.ServerRequests (5 ms)\n[15/28] InvalidationClientImplTest.ServerRequests (5 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[24851:24851:0108/084757.325225:33218192945:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e60 with delay 0\n[24851:24851:0108/084757.325292:33218193009:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.325581:33218193300:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000019d0 with delay 0\n[24851:24851:0108/084757.325629:33218193347:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001e60\n[24851:24851:0108/084757.325683:33218193399:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000019d0\n[24851:24851:0108/084757.325757:33218193474:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.325829:33218193549:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 0\n[24851:24851:0108/084757.325876:33218193591:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d20\n[24851:24851:0108/084757.325910:33218193627:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.325957:33218193675:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000019d0 with delay 0\n[24851:24851:0108/084757.326002:33218193718:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000019d0\n[24851:24851:0108/084757.326037:33218193754:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.326081:33218193798:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.326121:33218193837:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 0\n[24851:24851:0108/084757.326161:33218193877:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d20\n[24851:24851:0108/084757.326236:33218193955:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6223900842488648739\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.326283:33218194006:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.326339:33218194056:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000019d0 with delay 500\n[24851:24851:0108/084757.326380:33218194097:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.326422:33218194139:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000010e0 with delay 60000\n[24851:24851:0108/084757.326463:33218194180:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000019d0\n[24851:24851:0108/084757.326502:33218194222:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.326558:33218194288:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.326736:33218194459: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: \"6223900842488648739\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.326887:33218194605:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000019d0 with delay 0\n[24851:24851:0108/084757.326930:33218194647:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000019d0\n[24851:24851:0108/084757.327057:33218194774:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6223900842488648739\" 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[24851:24851:0108/084757.327133:33218194853:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6223900842488648739\"\n[24851:24851:0108/084757.327179:33218194896:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.327231:33218194949:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.327274:33218194992:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d20 with delay 1200000\n[24851:24851:0108/084757.327318:33218195039:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.327460:33218195177:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.327505:33218195228:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.327557:33218195294:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001e60 with delay 0\n[24851:24851:0108/084757.327640:33218195363: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[24851:24851:0108/084757.327697:33218195413:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001e60\n[24851:24851:0108/084757.327771:33218195488:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002150 with delay 0\n[24851:24851:0108/084757.327818:33218195540:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.327867:33218195584:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001f60 with delay 10000\n[24851:24851:0108/084757.327910:33218195626:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002150\n[24851:24851:0108/084757.327944:33218195661:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.327999:33218195724:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.328065:33218195783:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000002150 with delay 0\n[24851:24851:0108/084757.328105:33218195825:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000002150\n[24851:24851:0108/084757.328227:33218195945: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[24851:24851:0108/084757.328345:33218196062: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[24851:24851:0108/084757.328399:33218196116:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[24851:24851:0108/084757.328546:33218196264:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001f60\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[16/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[24851:24851:0108/084757.329385:33218197104:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002100 with delay 0\n[24851:24851:0108/084757.329449:33218197167:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.329772:33218197503:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.329831:33218197548:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002100\n[24851:24851:0108/084757.329883:33218197599:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c70\n[24851:24851:0108/084757.329954:33218197680:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.330028:33218197745:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001b00 with delay 0\n[24851:24851:0108/084757.330075:33218197791:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001b00\n[24851:24851:0108/084757.330110:33218197843:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.330172:33218197889:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.330209:33218197925:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c70\n[24851:24851:0108/084757.330246:33218197963:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.330287:33218198010:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.330334:33218198054:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001b00 with delay 0\n[24851:24851:0108/084757.330374:33218198089:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001b00\n[24851:24851:0108/084757.330445:33218198162:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6980672484580589176\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.330489:33218198205:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.330527:33218198244:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c70 with delay 500\n[24851:24851:0108/084757.330566:33218198299:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.330623:33218198343:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001b10 with delay 60000\n[24851:24851:0108/084757.330671:33218198390:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c70\n[24851:24851:0108/084757.330712:33218198429:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.330763:33218198482:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.330908:33218198627: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: \"-6980672484580589176\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.331035:33218198755:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c70 with delay 0\n[24851:24851:0108/084757.331076:33218198793:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c70\n[24851:24851:0108/084757.331264:33218198984:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6980672484580589176\" 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[24851:24851:0108/084757.331328:33218199045:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6980672484580589176\"\n[24851:24851:0108/084757.331408:33218199124:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.331453:33218199169:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.331493:33218199211:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001b00 with delay 1200000\n[24851:24851:0108/084757.331536:33218199259:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.331698:33218199418:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.331742:33218199469:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.331792:33218199509:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002100 with delay 0\n[24851:24851:0108/084757.331851:33218199570: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[24851:24851:0108/084757.331903:33218199620:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002100\n[24851:24851:0108/084757.331982:33218199699:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001970 with delay 0\n[24851:24851:0108/084757.332029:33218199747:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.332070:33218199793:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001b90 with delay 10000\n[24851:24851:0108/084757.332115:33218199831:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001970\n[24851:24851:0108/084757.332150:33218199872:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.332214:33218199931:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001970 with delay 0\n[24851:24851:0108/084757.332253:33218199970:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001970\n[24851:24851:0108/084757.332326:33218200042:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[24851:24851:0108/084757.332392:33218200111:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424\n[24851:24851:0108/084757.332433:33218200165:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000002100 with delay 500\n[24851:24851:0108/084757.332492:33218200209:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9320 with a delay 60000000, Now = 211469424\n[24851:24851:0108/084757.332531:33218200259:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c70 with delay 60000\n[24851:24851:0108/084757.332602:33218200320:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000002100\n[24851:24851:0108/084757.332644:33218200367:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.332702:33218200453:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.332775:33218200495:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[24851:24851:0108/084757.332923:33218200640: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[24851:24851:0108/084757.333021:33218200738:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.333077:33218200795:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000002100 with delay 0\n[24851:24851:0108/084757.333118:33218200835:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000002100\n[24851:24851:0108/084757.333242:33218200960: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[24851:24851:0108/084757.333316:33218201034: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[24851:24851:0108/084757.333359:33218201087:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[24851:24851:0108/084757.333472:33218201190:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[24851:24851:0108/084757.333677:33218201395:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001b90\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[17/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[24851:24851:0108/084757.334517:33218202236:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000021b0 with delay 0\n[24851:24851:0108/084757.334596:33218202313:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.334818:33218202538:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c60 with delay 0\n[24851:24851:0108/084757.334862:33218202579:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000021b0\n[24851:24851:0108/084757.334901:33218202617:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c60\n[24851:24851:0108/084757.334970:33218202690:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.335035:33218202753:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001910 with delay 0\n[24851:24851:0108/084757.335081:33218202796:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001910\n[24851:24851:0108/084757.335115:33218202832:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.335164:33218202881:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c60 with delay 0\n[24851:24851:0108/084757.335208:33218202924:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c60\n[24851:24851:0108/084757.335243:33218202969:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.335300:33218203021:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.335341:33218203066:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001910 with delay 0\n[24851:24851:0108/084757.335389:33218203105:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001910\n[24851:24851:0108/084757.335467:33218203184:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3357056424112350801\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.335516:33218203234:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.335560:33218203287:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c60 with delay 500\n[24851:24851:0108/084757.335609:33218203328:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.335661:33218203378:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ea0 with delay 60000\n[24851:24851:0108/084757.335700:33218203419:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c60\n[24851:24851:0108/084757.335740:33218203464:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.335805:33218203522:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.335944:33218203664: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: \"3357056424112350801\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.336066:33218203798:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c60 with delay 0\n[24851:24851:0108/084757.336123:33218203843:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c60\n[24851:24851:0108/084757.336253:33218203973:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3357056424112350801\" 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[24851:24851:0108/084757.336337:33218204054:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3357056424112350801\"\n[24851:24851:0108/084757.336382:33218204099:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.336427:33218204144:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.336467:33218204184:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001910 with delay 1200000\n[24851:24851:0108/084757.336509:33218204226:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.336647:33218204372:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.336722:33218204448:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.336772:33218204490:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000021b0 with delay 0\n[24851:24851:0108/084757.336833:33218204558: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[24851:24851:0108/084757.336892:33218204608:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000021b0\n[24851:24851:0108/084757.336965:33218204682:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.337011:33218204728:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.337051:33218204768:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002020 with delay 10000\n[24851:24851:0108/084757.337087:33218204803:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001da0\n[24851:24851:0108/084757.337121:33218204840:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.337183:33218204900:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.337241:33218204960:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001da0\n[24851:24851:0108/084757.337300:33218205017:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[24851:24851:0108/084757.337363:33218205081:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424\n[24851:24851:0108/084757.337402:33218205121:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000021b0 with delay 500\n[24851:24851:0108/084757.337442:33218205159:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424\n[24851:24851:0108/084757.337483:33218205200:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c60 with delay 60000\n[24851:24851:0108/084757.337583:33218205300:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000021b0\n[24851:24851:0108/084757.337625:33218205342:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.337683:33218205408:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.337729:33218205448:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[24851:24851:0108/084757.337874:33218205592: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[24851:24851:0108/084757.337998:33218205715:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000002020\n[24851:24851:0108/084757.338217:33218205933:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000001ea0\n[24851:24851:0108/084757.338255:33218205970:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000001c60\n[24851:24851:0108/084757.338312:33218206043: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[24851:24851:0108/084757.338370:33218206094:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[24851:24851:0108/084757.338476:33218206194: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[24851:24851:0108/084757.338522:33218206239:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424\n[24851:24851:0108/084757.338562:33218206291:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000001ea0 with delay 500\n[24851:24851:0108/084757.338614:33218206332:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424\n[24851:24851:0108/084757.338660:33218206377:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000002020 with delay 60000\n[24851:24851:0108/084757.338699:33218206426:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000001ea0\n[24851:24851:0108/084757.338747:33218206470:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.338808:33218206525:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.338847:33218206564:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[24851:24851:0108/084757.339001:33218206720: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 (5 ms)\n[18/28] InvalidationClientImplTest.NetworkTimeouts (5 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[24851:24851:0108/084757.339957:33218207677:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002150 with delay 0\n[24851:24851:0108/084757.340025:33218207743:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.340242:33218207959:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001fc0 with delay 0\n[24851:24851:0108/084757.340284:33218208113:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002150\n[24851:24851:0108/084757.340447:33218208163:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001fc0\n[24851:24851:0108/084757.340524:33218208241:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.340599:33218208317:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c60 with delay 0\n[24851:24851:0108/084757.340710:33218208426:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c60\n[24851:24851:0108/084757.340745:33218208462:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.340787:33218208504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001fc0 with delay 0\n[24851:24851:0108/084757.340826:33218208542:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001fc0\n[24851:24851:0108/084757.340862:33218208579:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.340905:33218208626:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.340947:33218208672:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c60 with delay 0\n[24851:24851:0108/084757.341000:33218208716:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c60\n[24851:24851:0108/084757.341073:33218208790:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2763264660845952354\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.341116:33218208834:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.341162:33218208891:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001fc0 with delay 500\n[24851:24851:0108/084757.341225:33218208942:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.341266:33218208994:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ea0 with delay 60000\n[24851:24851:0108/084757.341322:33218209042:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001fc0\n[24851:24851:0108/084757.341363:33218209080:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.341420:33218209153:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.341589:33218209309: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: \"-2763264660845952354\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.341731:33218209449:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001fc0 with delay 0\n[24851:24851:0108/084757.341772:33218209499:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001fc0\n[24851:24851:0108/084757.341920:33218209637:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2763264660845952354\" 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[24851:24851:0108/084757.341983:33218209702:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2763264660845952354\"\n[24851:24851:0108/084757.342026:33218209743:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.342078:33218209796:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.342121:33218209839:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c60 with delay 1200000\n[24851:24851:0108/084757.342169:33218209887:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.342306:33218210023:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.342347:33218210066:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.342393:33218210115:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002150 with delay 0\n[24851:24851:0108/084757.342462:33218210180: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[24851:24851:0108/084757.342514:33218210230:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002150\n[24851:24851:0108/084757.342611:33218210328:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.342673:33218210390:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.342714:33218210431:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000021b0 with delay 10000\n[24851:24851:0108/084757.342754:33218210470:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001da0\n[24851:24851:0108/084757.342789:33218210505:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.342853:33218210574:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.342911:33218210629:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.342951:33218210671:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001da0\n[24851:24851:0108/084757.343053:33218210817: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[24851:24851:0108/084757.343222:33218210941:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000021b0\n[24851:24851:0108/084757.343471:33218211189:INFO:invalidation-client-impl_test.cc(477)] Reg manager state: { client_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_summary: { num_registrations: 1 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } }\n[ OK ] InvalidationClientImplTest.NoRegistrationSummary (4 ms)\n[19/28] InvalidationClientImplTest.NoRegistrationSummary (4 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[24851:24851:0108/084757.344195:33218211915:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002060 with delay 0\n[24851:24851:0108/084757.344268:33218211986:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[24851:24851:0108/084757.344511:33218212229:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 0\n[24851:24851:0108/084757.344557:33218212297:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002060\n[24851:24851:0108/084757.344620:33218212336:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d20\n[24851:24851:0108/084757.344702:33218212420:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[24851:24851:0108/084757.344770:33218212487:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.344822:33218212538:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001da0\n[24851:24851:0108/084757.344857:33218212581:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[24851:24851:0108/084757.344916:33218212634:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 0\n[24851:24851:0108/084757.344960:33218212676:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d20\n[24851:24851:0108/084757.345002:33218212720:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[24851:24851:0108/084757.345060:33218212778:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424\n[24851:24851:0108/084757.345102:33218212820:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001da0 with delay 0\n[24851:24851:0108/084757.345142:33218212860:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001da0\n[24851:24851:0108/084757.345218:33218212939:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-8132417993286824849\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[24851:24851:0108/084757.345272:33218212990:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424\n[24851:24851:0108/084757.345313:33218213030:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 500\n[24851:24851:0108/084757.345354:33218213071:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424\n[24851:24851:0108/084757.345393:33218213110:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000021b0 with delay 60000\n[24851:24851:0108/084757.345435:33218213152:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d20\n[24851:24851:0108/084757.345474:33218213193:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.345529:33218213246:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[24851:24851:0108/084757.345730:33218213449: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: \"-8132417993286824849\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[24851:24851:0108/084757.345861:33218213579:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d20 with delay 0\n[24851:24851:0108/084757.345911:33218213628:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d20\n[24851:24851:0108/084757.346052:33218213777:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-8132417993286824849\" 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[24851:24851:0108/084757.346131:33218213851:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-8132417993286824849\"\n[24851:24851:0108/084757.346206:33218213927:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[24851:24851:0108/084757.346256:33218213974:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424\n[24851:24851:0108/084757.346299:33218214016:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001da0 with delay 1200000\n[24851:24851:0108/084757.346343:33218214071:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[24851:24851:0108/084757.346516:33218214234:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.346565:33218214297:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424\n[24851:24851:0108/084757.346628:33218214351:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002060 with delay 0\n[24851:24851:0108/084757.346706:33218214424: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[24851:24851:0108/084757.346760:33218214476:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002060\n[24851:24851:0108/084757.346837:33218214555:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001fc0 with delay 0\n[24851:24851:0108/084757.346893:33218214612:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424\n[24851:24851:0108/084757.346939:33218214656:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002150 with delay 10000\n[24851:24851:0108/084757.346979:33218214694:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001fc0\n[24851:24851:0108/084757.347014:33218214736:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[24851:24851:0108/084757.347118:33218214838:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000002150\n[24851:24851:0108/084757.347337:33218215053:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7010000021b0\n[24851:24851:0108/084757.351390:33218219108:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000001da0\n[24851:24851:0108/084757.351462:33218219179:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.351529:33218219246:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[24851:24851:0108/084757.351581:33218219298:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[24851:24851:0108/084757.351795:33218219514: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[24851:24851:0108/084757.351860:33218219578:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424\n[24851:24851:0108/084757.351903:33218219620:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7010000021b0 with delay 500\n[24851:24851:0108/084757.351947:33218219664:INFO:recurring-task.cc(55)] [Retry] Scheduling 1464 with a delay 1200000000, Now = 1411419424\n[24851:24851:0108/084757.351988:33218219705:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000002150 with delay 1200000\n[24851:24851:0108/084757.352029:33218219745:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7010000021b0\n[24851:24851:0108/084757.352070:33218219798:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.352180:33218219898:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[24851:24851:0108/084757.352223:33218219946:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[24851:24851:0108/084757.352501:33218220220: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 (10 ms)\n[20/28] InvalidationClientImplTest.Heartbeats (10 ms)\n[ RUN ] ProtocolHandlerTest.TokenMissing\n[24855:24855:0108/084757.373346:33218241077:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001280 with delay 0\n[24855:24855:0108/084757.373440:33218241159:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001280\n[24855:24855:0108/084757.373836:33218241555: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[24855:24855:0108/084757.373911:33218241629:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424\n[24855:24855:0108/084757.373961:33218241681:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001290 with delay 500\n[24855:24855:0108/084757.374006:33218241727:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001290\n[24855:24855:0108/084757.374118:33218241837:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[24855:24855:0108/084757.374164:33218241889:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\n[21/28] ProtocolHandlerTest.TokenMissing (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[24855:24855:0108/084757.374771:33218242490:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001290 with delay 0\n[24855:24855:0108/084757.374821:33218242546:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001290\n[24855:24855:0108/084757.374881:33218242604:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424\n[24855:24855:0108/084757.374947:33218242672:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001280 with delay 500\n[24855:24855:0108/084757.375000:33218242722:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001280\n[24855:24855:0108/084757.375114:33218242834:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[24855:24855:0108/084757.375206:33218242929: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[24855:24855:0108/084757.375289:33218243015: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[24855:24855:0108/084757.375453:33218243174: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[24855:24855:0108/084757.375611:33218243332: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[22/28] ProtocolHandlerTest.InvalidOutboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[24855:24855:0108/084757.376122:33218243841:INFO:protocol-handler.cc(139)] Incoming message: { }\n[24855:24855:0108/084757.376169:33218243890:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[24855:24855:0108/084757.376212:33218243929:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[23/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[24855:24855:0108/084757.376543:33218244261:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 698211352 with a delay 10000, Now = 0\n[24855:24855:0108/084757.376602:33218244320:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000001110 with delay 10\n[24855:24855:0108/084757.376649:33218244370:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000001110\n[24855:24855:0108/084757.376691:33218244417:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[24855:24855:0108/084757.376761:33218244483:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211352 with a delay 60000, Now = 10000\n[24855:24855:0108/084757.376815:33218244532:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001120 with delay 60\n[24855:24855:0108/084757.376856:33218244571:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x701000001120\n[24855:24855:0108/084757.376888:33218244603:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[24855:24855:0108/084757.376920:33218244635:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211352 with a delay 60000, Now = 70000\n[24855:24855:0108/084757.376958:33218244674:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x701000001110 with delay 60\n[24855:24855:0108/084757.376993:33218244717:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x701000001110\n[24855:24855:0108/084757.377035:33218244750:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[24855:24855:0108/084757.377066:33218244782:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211352 with a delay 60000, Now = 130000\n[24855:24855:0108/084757.377099:33218244814:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x701000001120 with delay 60\n[24855:24855:0108/084757.377131:33218244846:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x701000001120\n[24855:24855:0108/084757.377162:33218244877:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[24855:24855:0108/084757.377193:33218244908:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211352 with a delay 60000, Now = 190000\n[24855:24855:0108/084757.377225:33218244940:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x701000001110 with delay 60\n[24855:24855:0108/084757.377257:33218244972:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x701000001110\n[24855:24855:0108/084757.377287:33218245003:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[24855:24855:0108/084757.377318:33218245034:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211352 with a delay 60000, Now = 250000\n[24855:24855:0108/084757.377350:33218245065:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x701000001120 with delay 60\n[24855:24855:0108/084757.377382:33218245097:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x701000001120\n[24855:24855:0108/084757.377412:33218245127:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[24855:24855:0108/084757.377445:33218245160:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211352 with a delay 60000, Now = 310000\n[24855:24855:0108/084757.377477:33218245192:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x701000001110 with delay 60\n[24855:24855:0108/084757.377509:33218245224:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x701000001110\n[24855:24855:0108/084757.377546:33218245262:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[24855:24855:0108/084757.377587:33218245302:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211352 with a delay 60000, Now = 370000\n[24855:24855:0108/084757.377619:33218245334:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x701000001120 with delay 60\n[24855:24855:0108/084757.377651:33218245370:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x701000001120\n[24855:24855:0108/084757.377688:33218245409:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (1 ms)\n[24/28] RecurringTaskTest.PeriodicTask (1 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[24855:24855:0108/084757.377984:33218245711:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 698211168 with a delay 10000, Now = 0\n[24855:24855:0108/084757.378041:33218245759:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000001120 with delay 10\n[24855:24855:0108/084757.378080:33218245802:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000001120\n[24855:24855:0108/084757.378127:33218245859:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[24855:24855:0108/084757.378185:33218245903:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211168 with a delay 50000, Now = 10000\n[24855:24855:0108/084757.378235:33218245959:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001110 with delay 50\n[24855:24855:0108/084757.378286:33218246004:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x701000001110\n[24855:24855:0108/084757.378322:33218246043:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[24855:24855:0108/084757.378362:33218246080:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211168 with a delay 149000, Now = 60000\n[24855:24855:0108/084757.378404:33218246122:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x701000001120 with delay 149\n[24855:24855:0108/084757.378448:33218246166:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x701000001120\n[24855:24855:0108/084757.378488:33218246205:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[24855:24855:0108/084757.378524:33218246244:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211168 with a delay 248000, Now = 210000\n[24855:24855:0108/084757.378565:33218246294:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x701000001110 with delay 248\n[24855:24855:0108/084757.378616:33218246333:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x701000001110\n[24855:24855:0108/084757.378658:33218246390:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[24855:24855:0108/084757.378715:33218246432:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211168 with a delay 446000, Now = 460000\n[24855:24855:0108/084757.378756:33218246473:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x701000001120 with delay 446\n[24855:24855:0108/084757.378795:33218246522:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x701000001120\n[24855:24855:0108/084757.378843:33218246560:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[24855:24855:0108/084757.378882:33218246599:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211168 with a delay 842000, Now = 910000\n[24855:24855:0108/084757.378922:33218246645:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x701000001110 with delay 842\n[24855:24855:0108/084757.378971:33218246686:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x701000001110\n[24855:24855:0108/084757.379002:33218246717:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[24855:24855:0108/084757.379034:33218246749:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211168 with a delay 1040000, Now = 1760000\n[24855:24855:0108/084757.379066:33218246782:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x701000001120 with delay 1040\n[24855:24855:0108/084757.379102:33218246817:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x701000001120\n[24855:24855:0108/084757.379133:33218246848:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[24855:24855:0108/084757.379170:33218246885:INFO:recurring-task.cc(55)] [Retry] Scheduling 698211168 with a delay 1040000, Now = 2800000\n[24855:24855:0108/084757.379201:33218246917:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x701000001110 with delay 1040\n[24855:24855:0108/084757.379237:33218246952:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x701000001110\n[24855:24855:0108/084757.379267:33218246983:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms)\n[25/28] RecurringTaskTest.ExponentialBackoffTask (2 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[24855:24855:0108/084757.379535:33218247253:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 698211208 with a delay 10000, Now = 0\n[24855:24855:0108/084757.379589:33218247307:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000001110 with delay 10\n[24855:24855:0108/084757.379633:33218247350:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000001110\n[24855:24855:0108/084757.379669:33218247397:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[24855:24855:0108/084757.379727:33218247451:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 698211208 with a delay 10000, Now = 10000\n[24855:24855:0108/084757.379778:33218247497:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001110 with delay 10\n[24855:24855:0108/084757.379819:33218247536:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x701000001110\n[24855:24855:0108/084757.379858:33218247576:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (1 ms)\n[26/28] RecurringTaskTest.OneShotTask (1 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[24855:24855:0108/084757.380200:33218247918:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x701000001110 with delay 920\n[24855:24855:0108/084757.380248:33218247964:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000001110\n[24855:24855:0108/084757.380394:33218248112:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x701000001110 with delay 45000\n[24855:24855:0108/084757.380620:33218248338:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000001110\n[ OK ] ThrottleTest.ThrottlingScripted (0 ms)\n[27/28] ThrottleTest.ThrottlingScripted (0 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[24855:24855:0108/084757.380761:33218248478:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001110 with delay 990\n[24855:24855:0108/084757.380813:33218248537:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000001110\n[24855:24855:0108/084757.380865:33218248581:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.380907:33218248622:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x701000001110\n[24855:24855:0108/084757.380946:33218248661:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.380986:33218248701:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x701000001110\n[24855:24855:0108/084757.381018:33218248733:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.381058:33218248773:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x701000001110\n[24855:24855:0108/084757.381090:33218248805:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.381130:33218248845:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x701000001110\n[24855:24855:0108/084757.381161:33218248876:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.381201:33218248916:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x701000001110\n[24855:24855:0108/084757.381240:33218248958:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x701000001120 with delay 54000\n[24855:24855:0108/084757.381845:33218249560:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000001120\n[24855:24855:0108/084757.381881:33218249596:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.381921:33218249636:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x701000001120\n[24855:24855:0108/084757.381961:33218249676:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.382001:33218249716:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x701000001120\n[24855:24855:0108/084757.382033:33218249748:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.382073:33218249788:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x701000001120\n[24855:24855:0108/084757.382105:33218249819:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.382144:33218249859:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x701000001120\n[24855:24855:0108/084757.382176:33218249891:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.382216:33218249931:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x701000001120\n[24855:24855:0108/084757.382253:33218249967:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.382293:33218250008:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x701000001120\n[24855:24855:0108/084757.382325:33218250040:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x701000001110 with delay 54000\n[24855:24855:0108/084757.382908:33218250624:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x701000001110\n[24855:24855:0108/084757.382951:33218250666:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.382992:33218250707:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x701000001110\n[24855:24855:0108/084757.383024:33218250739:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.383064:33218250779:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x701000001110\n[24855:24855:0108/084757.383095:33218250810:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.383136:33218250850:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x701000001110\n[24855:24855:0108/084757.383167:33218250882:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.383207:33218250922:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x701000001110\n[24855:24855:0108/084757.383239:33218250954:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.383279:33218250994:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x701000001110\n[24855:24855:0108/084757.383311:33218251026:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.383351:33218251066:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x701000001110\n[24855:24855:0108/084757.383382:33218251098:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x701000001120 with delay 54000\n[24855:24855:0108/084757.383973:33218251689:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x701000001120\n[24855:24855:0108/084757.384008:33218251723:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.384048:33218251762:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x701000001120\n[24855:24855:0108/084757.384094:33218251809:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.384134:33218251848:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x701000001120\n[24855:24855:0108/084757.384166:33218251880:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.384205:33218251920:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x701000001120\n[24855:24855:0108/084757.384237:33218251952:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.384277:33218251992:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x701000001120\n[24855:24855:0108/084757.384327:33218252042:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.384369:33218252083:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x701000001120\n[24855:24855:0108/084757.384400:33218252115:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x701000001120 with delay 1000\n[24855:24855:0108/084757.384442:33218252157:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x701000001120\n[24855:24855:0108/084757.384474:33218252190:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x701000001110 with delay 54000\n[24855:24855:0108/084757.385070:33218252785:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x701000001110\n[24855:24855:0108/084757.385105:33218252820:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.385146:33218252860:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x701000001110\n[24855:24855:0108/084757.385177:33218252892:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.385218:33218252932:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x701000001110\n[24855:24855:0108/084757.385255:33218252969:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.385295:33218253009:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x701000001110\n[24855:24855:0108/084757.385326:33218253041:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.385366:33218253081:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x701000001110\n[24855:24855:0108/084757.385398:33218253113:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.385440:33218253155:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x701000001110\n[24855:24855:0108/084757.385472:33218253187:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x701000001110 with delay 1000\n[24855:24855:0108/084757.385512:33218253227:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x701000001110\n[24855:24855:0108/084757.385543:33218253259:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x701000001120 with delay 54000\n[24855:24855:0108/084757.386128:33218253843:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x701000001120\n[ OK ] ThrottleTest.ThrottlingStorm (6 ms)\n[28/28] ThrottleTest.ThrottlingStorm (6 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "2dbb0fb21e7a564ee2ec4c67653bb0c7ca50d2f6", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "42472e7c530e1011", "server_versions": [ "3945-402d3be" ], "started_ts": "2019-01-08T16:47:50.918908", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:linux_chromium_msan_rel_ng", "buildnumber:1336", "cpu:x86-64", "data:049a506d6c5df3e3d29e82cf9ea59a5b51916b59", "gerrit:https://chromium-review.googlesource.com/c/1401445/1", "gpu:none", "master:tryserver.chromium.linux", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "patch_project:chromium/src", "pool:Chrome", "priority:30", "project:chromium", "purpose:ManualTS", "purpose:luci", "purpose:pre-commit", "service_account:none", "slavename:swarm1906-c4", "spec_name:chromium.try:linux_chromium_msan_rel_ng", "stepname:cacheinvalidation_unittests (with patch)", "swarming.pool.template:none", "swarming.pool.version:33fd91feea2c66c90fd47caf94d8f3c611e00d7d", "user:None" ], "task_id": "4248effe45c24010" } ] }