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

{ "shards": [ { "bot_dimensions": [ { "key": "caches", "value": [ "swarming_module_cache_vpython" ] }, { "key": "cores", "value": [ "8" ] }, { "key": "cpu", "value": [ "x86", "x86-64", "x86-64-Broadwell_GCE", "x86-64-avx2" ] }, { "key": "gce", "value": [ "1" ] }, { "key": "gpu", "value": [ "none" ] }, { "key": "id", "value": [ "chrome-extra-trusty-104-tuwc" ] }, { "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": [ "4216-cf4a3cd" ] }, { "key": "zone", "value": [ "us", "us-central", "us-central1", "us-central1-b" ] } ], "bot_id": "chrome-extra-trusty-104-tuwc", "bot_version": "c7f0c187ee2160053ce935aa86119b526086da1e165dea02547e2f5a35dc9e3f", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "nFftZl2kFquaI2EUmPGwzbc5sIbCocl9L55UeASqlLsC" }, "packages": [ { "package_name": "infra/python/cpython/linux-amd64", "path": ".swarming_module", "version": "46c0c897ca0f053799ee41fd148bb7a47232df47" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": ".swarming_module", "version": "2737ea8ed9b958f4d5aa9ffe106115a649ada241" }, { "package_name": "infra/tools/luci/vpython-native/linux-amd64", "path": ".swarming_module", "version": "OAXVAmcUSrvDygYUrCDzv20LRono9938YOHPu0zKowgC" }, { "package_name": "infra/tools/luci/vpython/linux-amd64", "path": ".swarming_module", "version": "ucaOciwAE9aweCUDOrmSvyiwrjmbywuB0NzAGUXIHjAC" } ] }, "completed_ts": "2019-03-24T07:32:24.339882", "cost_saved_usd": 0.000833177226923837, "created_ts": "2019-03-24T18:10:17.515144", "deduped_from": "43c76ec9ef089a11", "duration": 0.8741381168365479, "modified_ts": "2019-03-24T18:10:17.634857", "name": "cacheinvalidation_unittests/Ubuntu-14.04/dfdb629dad/Linux ChromiumOS MSan Tests/11978", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n MSAN_OPTIONS=symbolize=0 handle_abort=1\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioJVGO52/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[2963:2963:0324/003223.117142:3788240657:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000520 with delay 0\n[2963:2963:0324/003223.117560:3788241029:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000520\n[2963:2963:0324/003223.117912:3788241380: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[2963:2963:0324/003223.117981:3788241452:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 500000, Now = 210919424\n[2963:2963:0324/003223.118029:3788241497:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005c0 with delay 500\n[2963:2963:0324/003223.118098:3788241565:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005c0\n[2963:2963:0324/003223.118384:3788241853: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 (5 ms)\n[1/28] ProtocolHandlerTest.SendInitializeOnly (5 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[2963:2963:0324/003223.119671:3788243140: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 (0 ms)\n[2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (0 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[2963:2963:0324/003223.120228:3788243703:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[2963:2963:0324/003223.120350:3788243818:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004e0 with delay 0\n[2963:2963:0324/003223.120406:3788243876:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000460 with delay 0\n[2963:2963:0324/003223.120480:3788243956:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004a0 with delay 0\n[2963:2963:0324/003223.120542:3788244037:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000450 with delay 0\n[2963:2963:0324/003223.120638:3788244109:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0\n[2963:2963:0324/003223.121057:3788244534:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[2963:2963:0324/003223.121227:3788244697: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[2963:2963:0324/003223.121290:3788244758:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2408 with a delay 500000, Now = 210919424\n[2963:2963:0324/003223.121338:3788244806:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000610 with delay 500\n[2963:2963:0324/003223.121386:3788244853:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004e0\n[2963:2963:0324/003223.121431:3788244898:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000460\n[2963:2963:0324/003223.121471:3788244940:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004a0\n[2963:2963:0324/003223.121514:3788244980:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000450\n[2963:2963:0324/003223.121552:3788245018:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490\n[2963:2963:0324/003223.121618:3788245089:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[2963:2963:0324/003223.121683:3788245150:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000610\n[2963:2963:0324/003223.121843:3788245311:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[2963:2963:0324/003223.123079:3788246548: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 (5 ms)\n[3/28] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[2963:2963:0324/003223.124822:3788248292: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[2963:2963:0324/003223.125578:3788249047: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[2963:2963:0324/003223.125670:3788249138: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[2963:2963:0324/003223.125766:3788249233: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[2963:2963:0324/003223.125865:3788249332: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[2963:2963:0324/003223.126421:3788249890: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[2963:2963:0324/003223.126549:3788250016:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (0 ms)\n[6/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[2963:2963:0324/003223.127067:3788250535:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[7/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[2963:2963:0324/003223.127611:3788251080: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[2963:2963:0324/003223.127681:3788251149:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000003e0 with delay 0\n[2963:2963:0324/003223.127726:3788251193:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000003e0\n[2963:2963:0324/003223.127812:3788251280: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[2963:2963:0324/003223.127866:3788251334:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2792 with a delay 500000, Now = 210919424\n[2963:2963:0324/003223.127910:3788251377:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000003f0 with delay 500\n[2963:2963:0324/003223.127965:3788251441:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003f0\n[2963:2963:0324/003223.128016:3788251483:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (47 ms)\n[8/28] ProtocolHandlerTest.ConfigMessage (47 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[2963:2963:0324/003223.174522:3788297993:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.ErrorMessage (0 ms)\n[9/28] ProtocolHandlerTest.ErrorMessage (0 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[2963:2963:0324/003223.175081:3788298549:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.TokenMismatch (1 ms)\n[10/28] ProtocolHandlerTest.TokenMismatch (1 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[2961:2961:0324/003223.098237:3788221751:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000620 with delay 0\n[2961:2961:0324/003223.098719:3788222188:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.099270:3788222739:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 0\n[2961:2961:0324/003223.099358:3788222864:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000620\n[2961:2961:0324/003223.099443:3788222911:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000800\n[2961:2961:0324/003223.099659:3788223128:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.099941:3788223411:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000850 with delay 0\n[2961:2961:0324/003223.100061:3788223529:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000850\n[2961:2961:0324/003223.100128:3788223599:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.100178:3788223678:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 0\n[2961:2961:0324/003223.100257:3788223725:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000800\n[2961:2961:0324/003223.100346:3788223824:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.100415:3788223885:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.100464:3788223931:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000850 with delay 0\n[2961:2961:0324/003223.100517:3788223985:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000850\n[2961:2961:0324/003223.100810:3788224279:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3615392383166341584\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.100866:3788224334:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2504 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.100916:3788224383:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 500\n[2961:2961:0324/003223.100962:3788224431:INFO:recurring-task.cc(55)] [Retry] Scheduling 2120 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.101008:3788224480:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007c0 with delay 60000\n[2961:2961:0324/003223.101070:3788224537:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000800\n[2961:2961:0324/003223.101166:3788224634:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.101274:3788224741:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.101472:3788224940: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: \"3615392383166341584\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.101817:3788225286:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000800 with delay 0\n[2961:2961:0324/003223.101867:3788225344:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000800\n[2961:2961:0324/003223.102112:3788225592:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3615392383166341584\" 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[2961:2961:0324/003223.102206:3788225674:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3615392383166341584\"\n[2961:2961:0324/003223.102285:3788225753:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.102339:3788225807:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.102383:3788225850:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000840 with delay 1200000\n[2961:2961:0324/003223.102429:3788225896:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.102701:3788226169:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.102751:3788226220:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 904 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.102793:3788226260:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000850 with delay 0\n[2961:2961:0324/003223.102860:3788226327: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[2961:2961:0324/003223.102914:3788226381:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000850\n[2961:2961:0324/003223.103045:3788226513:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000870 with delay 0\n[2961:2961:0324/003223.103103:3788226570:INFO:recurring-task.cc(55)] [Retry] Scheduling 904 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.103157:3788226624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000620 with delay 10000\n[2961:2961:0324/003223.103197:3788226664:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000870\n[2961:2961:0324/003223.103234:3788226701:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (9 ms)\n[11/28] InvalidationClientImplTest.Start (9 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[2961:2961:0324/003223.104056:3788227530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0\n[2961:2961:0324/003223.104148:3788227616:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)\n[12/28] InvalidationClientImplTest.GenerateNonce (1 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[2961:2961:0324/003223.104724:3788228193:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000830 with delay 0\n[2961:2961:0324/003223.104793:3788228260:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.105240:3788228708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000890 with delay 0\n[2961:2961:0324/003223.105291:3788228759:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000830\n[2961:2961:0324/003223.105340:3788228807:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000890\n[2961:2961:0324/003223.105413:3788228883:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.105491:3788228967:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0\n[2961:2961:0324/003223.105554:3788229022:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0\n[2961:2961:0324/003223.105595:3788229063:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.105635:3788229103:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000890 with delay 0\n[2961:2961:0324/003223.105681:3788229148:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000890\n[2961:2961:0324/003223.105719:3788229186:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.105765:3788229232:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.105803:3788229271:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0\n[2961:2961:0324/003223.105845:3788229312:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0\n[2961:2961:0324/003223.105919:3788229386:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2839232980790330387\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.105965:3788229433:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2120 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.106004:3788229474:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000890 with delay 500\n[2961:2961:0324/003223.106052:3788229520:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.106093:3788229560:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 60000\n[2961:2961:0324/003223.106157:3788229625:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000890\n[2961:2961:0324/003223.106200:3788229668:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.106253:3788229720:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.106397:3788229864: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: \"-2839232980790330387\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.106536:3788230004:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 0\n[2961:2961:0324/003223.106583:3788230050:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000890\n[2961:2961:0324/003223.106713:3788230181:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2839232980790330387\" 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[2961:2961:0324/003223.106777:3788230245:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2839232980790330387\"\n[2961:2961:0324/003223.106827:3788230295:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.106875:3788230343:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.106916:3788230388:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008c0 with delay 1200000\n[2961:2961:0324/003223.106963:3788230431:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.107097:3788230565:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.107157:3788230625:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.107204:3788230672:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008d0 with delay 0\n[2961:2961:0324/003223.107264:3788230732: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[2961:2961:0324/003223.107316:3788230783:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008d0\n[2961:2961:0324/003223.107391:3788230859:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0\n[2961:2961:0324/003223.107443:3788230910:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.107484:3788230951:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000830 with delay 10000\n[2961:2961:0324/003223.107532:3788230999:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0\n[2961:2961:0324/003223.107569:3788231038:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.107657:3788231125:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008f0 with delay 0\n[2961:2961:0324/003223.107705:3788231172:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000008f0\n[2961:2961:0324/003223.107759:3788231226:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[2961:2961:0324/003223.107808:3788231275:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[2961:2961:0324/003223.107853:3788231320:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[2961:2961:0324/003223.107984:3788231454:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2120 with a delay 500000, Now = 211469424\n[2961:2961:0324/003223.108033:3788231501:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008d0 with delay 500\n[2961:2961:0324/003223.108077:3788231545:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2792 with a delay 60000000, Now = 211469424\n[2961:2961:0324/003223.108115:3788231596:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008e0 with delay 60000\n[2961:2961:0324/003223.108192:3788231665:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008d0\n[2961:2961:0324/003223.108261:3788231731:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.108328:3788231795:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.108367:3788231834:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2961:2961:0324/003223.108582:3788232051: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[2961:2961:0324/003223.108695:3788232163:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.108886:3788232355:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7010000008d0 with delay 0\n[2961:2961:0324/003223.108931:3788232399:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008d0\n[2961:2961:0324/003223.109192:3788232660: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[2961:2961:0324/003223.109372:3788232843: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[2961:2961:0324/003223.109482:3788232950:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[2961:2961:0324/003223.109623:3788233091:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[2961:2961:0324/003223.109722:3788233190:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[2961:2961:0324/003223.110064:3788233533:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000830\n[ OK ] InvalidationClientImplTest.Register (7 ms)\n[13/28] InvalidationClientImplTest.Register (7 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[2961:2961:0324/003223.111883:3788235352:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000770 with delay 0\n[2961:2961:0324/003223.111957:3788235424:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.112451:3788235921:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 0\n[2961:2961:0324/003223.112518:3788235986:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000770\n[2961:2961:0324/003223.112593:3788236067:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005d0\n[2961:2961:0324/003223.112682:3788236150:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.112751:3788236218:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0\n[2961:2961:0324/003223.112802:3788236270:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0\n[2961:2961:0324/003223.112841:3788236308:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.112882:3788236350:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 0\n[2961:2961:0324/003223.112922:3788236389:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005d0\n[2961:2961:0324/003223.112960:3788236427:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.113014:3788236482:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.113057:3788236524:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0\n[2961:2961:0324/003223.113096:3788236564:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0\n[2961:2961:0324/003223.113187:3788236655:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-9221452888028141075\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.113235:3788236702:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.113276:3788236744:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 500\n[2961:2961:0324/003223.113320:3788236788:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.113361:3788236829:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 60000\n[2961:2961:0324/003223.113416:3788236883:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005d0\n[2961:2961:0324/003223.113456:3788236923:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.113517:3788236985:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.113664:3788237131: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: \"-9221452888028141075\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.113796:3788237264:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005d0 with delay 0\n[2961:2961:0324/003223.113842:3788237309:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005d0\n[2961:2961:0324/003223.113970:3788237437:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-9221452888028141075\" 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[2961:2961:0324/003223.114038:3788237506:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-9221452888028141075\"\n[2961:2961:0324/003223.114081:3788237548:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.114141:3788237609:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.114185:3788237652:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 1200000\n[2961:2961:0324/003223.114226:3788237695:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.114357:3788237825:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.114400:3788237868:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1416 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.114442:3788237910:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0\n[2961:2961:0324/003223.114516:3788237984: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[2961:2961:0324/003223.114575:3788238042:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0\n[2961:2961:0324/003223.114653:3788238120:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000920 with delay 0\n[2961:2961:0324/003223.114703:3788238173:INFO:recurring-task.cc(55)] [Retry] Scheduling 1416 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.114745:3788238212:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000770 with delay 10000\n[2961:2961:0324/003223.114785:3788238252:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000920\n[2961:2961:0324/003223.114822:3788238289:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.114880:3788238347:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.114955:3788238423:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000920 with delay 0\n[2961:2961:0324/003223.114997:3788238467:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000920\n[2961:2961:0324/003223.115234:3788238702: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[2961:2961:0324/003223.115333:3788238801: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[2961:2961:0324/003223.115425:3788238901: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[2961:2961:0324/003223.115594:3788239062: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[2961:2961:0324/003223.115704:3788239171: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[2961:2961:0324/003223.115803:3788239270:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000920 with delay 0\n[2961:2961:0324/003223.115847:3788239314:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7010000008f0 with delay 0\n[2961:2961:0324/003223.115888:3788239355:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000900 with delay 0\n[2961:2961:0324/003223.115926:3788239393:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000920\n[2961:2961:0324/003223.115984:3788239452:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2984 with a delay 500000, Now = 211519424\n[2961:2961:0324/003223.116029:3788239497:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7010000005d0 with delay 500\n[2961:2961:0324/003223.116074:3788239541:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7010000008f0\n[2961:2961:0324/003223.116132:3788239600:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000900\n[2961:2961:0324/003223.116193:3788239660:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7010000005d0\n[2961:2961:0324/003223.116239:3788239714:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.116313:3788239781:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.116357:3788239824:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2961:2961:0324/003223.116599:3788240071:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: \"2\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } }\n[ OK ] InvalidationClientImplTest.Invalidations (6 ms)\n[14/28] InvalidationClientImplTest.Invalidations (6 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[2961:2961:0324/003223.117415:3788240884:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000860 with delay 0\n[2961:2961:0324/003223.117486:3788240954:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.117734:3788241202:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0\n[2961:2961:0324/003223.117785:3788241253:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000860\n[2961:2961:0324/003223.117825:3788241291:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0\n[2961:2961:0324/003223.117899:3788241366:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.117963:3788241431:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0\n[2961:2961:0324/003223.118016:3788241483:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0\n[2961:2961:0324/003223.118055:3788241530:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.118109:3788241591:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0\n[2961:2961:0324/003223.118165:3788241633:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0\n[2961:2961:0324/003223.118205:3788241673:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.118249:3788241717:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.118291:3788241758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0\n[2961:2961:0324/003223.118330:3788241797:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0\n[2961:2961:0324/003223.118406:3788241874:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1901061889552771097\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.118452:3788241920:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.118494:3788241968:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 500\n[2961:2961:0324/003223.118541:3788242010:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.118582:3788242049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006f0 with delay 60000\n[2961:2961:0324/003223.118641:3788242108:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0\n[2961:2961:0324/003223.118681:3788242153:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.118737:3788242205:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.118908:3788242377: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: \"1901061889552771097\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.119032:3788242501:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006c0 with delay 0\n[2961:2961:0324/003223.119081:3788242557:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0\n[2961:2961:0324/003223.119238:3788242706:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1901061889552771097\" 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[2961:2961:0324/003223.119303:3788242770:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1901061889552771097\"\n[2961:2961:0324/003223.119345:3788242814:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.119390:3788242858:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.119434:3788242902:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005a0 with delay 1200000\n[2961:2961:0324/003223.119479:3788242946:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.119619:3788243087:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.119666:3788243133:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.119705:3788243172:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008d0 with delay 0\n[2961:2961:0324/003223.119772:3788243242: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[2961:2961:0324/003223.119829:3788243296:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008d0\n[2961:2961:0324/003223.119904:3788243372:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005c0 with delay 0\n[2961:2961:0324/003223.119956:3788243424:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.119995:3788243466:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000860 with delay 10000\n[2961:2961:0324/003223.120041:3788243508:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005c0\n[2961:2961:0324/003223.120078:3788243545:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.120148:3788243619:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.120213:3788243681:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000005c0 with delay 0\n[2961:2961:0324/003223.120259:3788243727:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000005c0\n[2961:2961:0324/003223.120407:3788243875: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[2961:2961:0324/003223.120511:3788243979: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[2961:2961:0324/003223.120592:3788244062:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[2961:2961:0324/003223.120642:3788244112:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 3464 with a delay 500000, Now = 211469424\n[2961:2961:0324/003223.120690:3788244158:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008d0 with delay 500\n[2961:2961:0324/003223.120735:3788244211:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[2961:2961:0324/003223.121001:3788244473: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[2961:2961:0324/003223.121088:3788244558:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008d0\n[2961:2961:0324/003223.121146:3788244614:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.121227:3788244696:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.121269:3788244736:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2961:2961:0324/003223.122484:3788245953: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[2961:2961:0324/003223.122834:3788246302:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000860\n[ OK ] InvalidationClientImplTest.ServerRequests (7 ms)\n[15/28] InvalidationClientImplTest.ServerRequests (7 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[2961:2961:0324/003223.124534:3788248024:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 0\n[2961:2961:0324/003223.124641:3788248109:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.124940:3788248409:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0\n[2961:2961:0324/003223.124989:3788248457:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004f0\n[2961:2961:0324/003223.125036:3788248503:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0\n[2961:2961:0324/003223.125111:3788248591:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.125194:3788248662:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 0\n[2961:2961:0324/003223.125249:3788248717:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000480\n[2961:2961:0324/003223.125288:3788248755:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.125329:3788248796:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0\n[2961:2961:0324/003223.125370:3788248837:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0\n[2961:2961:0324/003223.125407:3788248874:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.125450:3788248917:INFO:recurring-task.cc(55)] [Startup] Scheduling 2984 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.125491:3788248958:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 0\n[2961:2961:0324/003223.125555:3788249022:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000480\n[2961:2961:0324/003223.125633:3788249100:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-3358436094001469644\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.125679:3788249146:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2600 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.125721:3788249188:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 500\n[2961:2961:0324/003223.125767:3788249234:INFO:recurring-task.cc(55)] [Retry] Scheduling 2984 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.125806:3788249273:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000470 with delay 60000\n[2961:2961:0324/003223.125860:3788249327:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0\n[2961:2961:0324/003223.125901:3788249368:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.125954:3788249421:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.126098:3788249566: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: \"-3358436094001469644\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.126246:3788249715:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006c0 with delay 0\n[2961:2961:0324/003223.126294:3788249761:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0\n[2961:2961:0324/003223.126428:3788249895:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-3358436094001469644\" 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[2961:2961:0324/003223.126493:3788249970:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-3358436094001469644\"\n[2961:2961:0324/003223.126551:3788250018:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.126595:3788250062:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.126640:3788250108:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004d0 with delay 1200000\n[2961:2961:0324/003223.126684:3788250151:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.126817:3788250285:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.126862:3788250330:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.126901:3788250368:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000480 with delay 0\n[2961:2961:0324/003223.126962:3788250429: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[2961:2961:0324/003223.127015:3788250482:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000480\n[2961:2961:0324/003223.127092:3788250560:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000380 with delay 0\n[2961:2961:0324/003223.127156:3788250624:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.127196:3788250665:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004f0 with delay 10000\n[2961:2961:0324/003223.127236:3788250703:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000380\n[2961:2961:0324/003223.127273:3788250740:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.127331:3788250798:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.127388:3788250856:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000380 with delay 0\n[2961:2961:0324/003223.127429:3788250897:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000380\n[2961:2961:0324/003223.127559:3788251026: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[2961:2961:0324/003223.127638:3788251106: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[2961:2961:0324/003223.127681:3788251151:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[2961:2961:0324/003223.128045:3788251513:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000004f0\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[16/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[2961:2961:0324/003223.129759:3788253228:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000740 with delay 0\n[2961:2961:0324/003223.129831:3788253298:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.130193:3788253662:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0\n[2961:2961:0324/003223.130246:3788253714:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000740\n[2961:2961:0324/003223.130286:3788253752:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820\n[2961:2961:0324/003223.130361:3788253829:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.130437:3788253906:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000900 with delay 0\n[2961:2961:0324/003223.130493:3788253968:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000900\n[2961:2961:0324/003223.130541:3788254008:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.130583:3788254050:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0\n[2961:2961:0324/003223.130628:3788254095:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820\n[2961:2961:0324/003223.130666:3788254135:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.130711:3788254179:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.130756:3788254224:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000900 with delay 0\n[2961:2961:0324/003223.130796:3788254263:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000900\n[2961:2961:0324/003223.130875:3788254345:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"227079018968583465\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.130929:3788254397:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.130971:3788254439:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 500\n[2961:2961:0324/003223.131013:3788254483:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.131055:3788254522:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 60000\n[2961:2961:0324/003223.131107:3788254585:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820\n[2961:2961:0324/003223.131159:3788254629:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.131213:3788254681:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.131352:3788254834: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: \"227079018968583465\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.131490:3788254966:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000820 with delay 0\n[2961:2961:0324/003223.131543:3788255010:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820\n[2961:2961:0324/003223.131675:3788255143:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"227079018968583465\" 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[2961:2961:0324/003223.131744:3788255212:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"227079018968583465\"\n[2961:2961:0324/003223.131787:3788255255:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.131832:3788255300:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.131875:3788255343:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 1200000\n[2961:2961:0324/003223.131920:3788255387:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.132051:3788255519:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.132094:3788255564:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.132154:3788255622:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000900 with delay 0\n[2961:2961:0324/003223.132215:3788255682: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[2961:2961:0324/003223.132267:3788255734:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000900\n[2961:2961:0324/003223.132343:3788255811:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 0\n[2961:2961:0324/003223.132395:3788255862:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.132434:3788255901:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000740 with delay 10000\n[2961:2961:0324/003223.132475:3788255942:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000910\n[2961:2961:0324/003223.132519:3788255986:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.132613:3788256083:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000910 with delay 0\n[2961:2961:0324/003223.132661:3788256128:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000910\n[2961:2961:0324/003223.132718:3788256185:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[2961:2961:0324/003223.132783:3788256251:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2984 with a delay 500000, Now = 211469424\n[2961:2961:0324/003223.132826:3788256294:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000900 with delay 500\n[2961:2961:0324/003223.132869:3788256336:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2120 with a delay 60000000, Now = 211469424\n[2961:2961:0324/003223.132907:3788256375:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000920 with delay 60000\n[2961:2961:0324/003223.132965:3788256443:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000900\n[2961:2961:0324/003223.133026:3788256494:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.133081:3788256548:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.133134:3788256602:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2961:2961:0324/003223.133279:3788256746: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[2961:2961:0324/003223.133384:3788256853:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.133448:3788256922:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000900 with delay 0\n[2961:2961:0324/003223.133496:3788256973:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000900\n[2961:2961:0324/003223.133627:3788257094: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[2961:2961:0324/003223.133715:3788257183: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[2961:2961:0324/003223.133763:3788257231:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[2961:2961:0324/003223.133864:3788257332:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[2961:2961:0324/003223.134193:3788257661:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000740\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms)\n[17/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[2961:2961:0324/003223.135821:3788259289:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005c0 with delay 0\n[2961:2961:0324/003223.135891:3788259359:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.136149:3788259618:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 0\n[2961:2961:0324/003223.136198:3788259666:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005c0\n[2961:2961:0324/003223.136241:3788259708:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004f0\n[2961:2961:0324/003223.136313:3788259781:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.136384:3788259852:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007d0 with delay 0\n[2961:2961:0324/003223.136433:3788259900:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007d0\n[2961:2961:0324/003223.136471:3788259940:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.136520:3788259987:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 0\n[2961:2961:0324/003223.136594:3788260063:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004f0\n[2961:2961:0324/003223.136638:3788260105:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.136682:3788260152:INFO:recurring-task.cc(55)] [Startup] Scheduling 2888 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.136724:3788260192:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007d0 with delay 0\n[2961:2961:0324/003223.136767:3788260234:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007d0\n[2961:2961:0324/003223.136842:3788260317:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3145009066511244932\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.136905:3788260376:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2696 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.136949:3788260416:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 500\n[2961:2961:0324/003223.136989:3788260457:INFO:recurring-task.cc(55)] [Retry] Scheduling 2888 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.137033:3788260501:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 60000\n[2961:2961:0324/003223.137085:3788260553:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004f0\n[2961:2961:0324/003223.137140:3788260608:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.137196:3788260663:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.137359:3788260827: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: \"3145009066511244932\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.137492:3788260969:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004f0 with delay 0\n[2961:2961:0324/003223.137548:3788261015:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004f0\n[2961:2961:0324/003223.137674:3788261142:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3145009066511244932\" 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[2961:2961:0324/003223.137735:3788261203:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3145009066511244932\"\n[2961:2961:0324/003223.137780:3788261247:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.137836:3788261304:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.137878:3788261345:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 1200000\n[2961:2961:0324/003223.137922:3788261389:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.138059:3788261527:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.138109:3788261588:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.138166:3788261633:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007d0 with delay 0\n[2961:2961:0324/003223.138226:3788261694: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[2961:2961:0324/003223.138277:3788261744:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000007d0\n[2961:2961:0324/003223.138355:3788261823:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003f0 with delay 0\n[2961:2961:0324/003223.138407:3788261875:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.138448:3788261915:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005c0 with delay 10000\n[2961:2961:0324/003223.138493:3788261968:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003f0\n[2961:2961:0324/003223.138540:3788262007:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.138601:3788262068:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000003f0 with delay 0\n[2961:2961:0324/003223.138644:3788262111:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000003f0\n[2961:2961:0324/003223.138697:3788262164:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[2961:2961:0324/003223.138764:3788262231:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2696 with a delay 500000, Now = 211469424\n[2961:2961:0324/003223.138804:3788262273:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000007d0 with delay 500\n[2961:2961:0324/003223.138847:3788262314:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2504 with a delay 60000000, Now = 211469424\n[2961:2961:0324/003223.138887:3788262355:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000490 with delay 60000\n[2961:2961:0324/003223.138945:3788262412:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000007d0\n[2961:2961:0324/003223.138985:3788262454:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.139043:3788262518:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.139099:3788262569:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2961:2961:0324/003223.139257:3788262730: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[2961:2961:0324/003223.139578:3788263046:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000005c0\n[2961:2961:0324/003223.140809:3788264277:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7010000005f0\n[2961:2961:0324/003223.140867:3788264333:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000490\n[2961:2961:0324/003223.140929:3788264397: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[2961:2961:0324/003223.140975:3788264443:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[2961:2961:0324/003223.141064:3788264532: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[2961:2961:0324/003223.141110:3788264588:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2696 with a delay 500000, Now = 271469424\n[2961:2961:0324/003223.141165:3788264632:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7010000005f0 with delay 500\n[2961:2961:0324/003223.141206:3788264674:INFO:recurring-task.cc(55)] [Retry] Scheduling 2504 with a delay 60000000, Now = 271469424\n[2961:2961:0324/003223.141245:3788264714:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7010000005c0 with delay 60000\n[2961:2961:0324/003223.141298:3788264766:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7010000005f0\n[2961:2961:0324/003223.141340:3788264807:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.141395:3788264863:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.141443:3788264910:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2961:2961:0324/003223.141602:3788265069:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 1 registration_digest: \"\\327\\003\\047\\242\\324@\\3740-O\\354\\3229\\352\\000\\231\\340\\204\\224\\323\" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: \"3\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } server_registration_summary_requested: true } }\n[ OK ] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[18/28] InvalidationClientImplTest.NetworkTimeouts (8 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[2961:2961:0324/003223.143543:3788267012:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007e0 with delay 0\n[2961:2961:0324/003223.143614:3788267081:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.143857:3788267325:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[2961:2961:0324/003223.143904:3788267372:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007e0\n[2961:2961:0324/003223.143944:3788267410:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[2961:2961:0324/003223.144026:3788267494:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.144092:3788267560:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0\n[2961:2961:0324/003223.144159:3788267627:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490\n[2961:2961:0324/003223.144198:3788267665:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.144240:3788267707:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0\n[2961:2961:0324/003223.144280:3788267747:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0\n[2961:2961:0324/003223.144317:3788267789:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.144365:3788267832:INFO:recurring-task.cc(55)] [Startup] Scheduling 3464 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.144406:3788267873:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0\n[2961:2961:0324/003223.144445:3788267912:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490\n[2961:2961:0324/003223.144526:3788267994:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1586014730332081298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.144664:3788268132:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3080 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.144710:3788268177:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 500\n[2961:2961:0324/003223.144749:3788268216:INFO:recurring-task.cc(55)] [Retry] Scheduling 3464 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.144789:3788268271:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000780 with delay 60000\n[2961:2961:0324/003223.144860:3788268328:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0\n[2961:2961:0324/003223.144900:3788268367:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.144958:3788268426:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.145107:3788268586: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: \"1586014730332081298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.145243:3788268713:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0\n[2961:2961:0324/003223.145289:3788268757:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0\n[2961:2961:0324/003223.145423:3788268890:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1586014730332081298\" 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[2961:2961:0324/003223.145488:3788268956:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1586014730332081298\"\n[2961:2961:0324/003223.145539:3788269009:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.145596:3788269074:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.145663:3788269131:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007d0 with delay 1200000\n[2961:2961:0324/003223.145708:3788269175:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.145841:3788269309:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.145887:3788269354:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.145926:3788269394:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000490 with delay 0\n[2961:2961:0324/003223.145986:3788269456: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[2961:2961:0324/003223.146048:3788269515:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000490\n[2961:2961:0324/003223.146135:3788269603:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003f0 with delay 0\n[2961:2961:0324/003223.146189:3788269656:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.146234:3788269704:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007e0 with delay 10000\n[2961:2961:0324/003223.146284:3788269751:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003f0\n[2961:2961:0324/003223.146321:3788269788:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.146382:3788269849:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.146433:3788269904:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000003f0 with delay 0\n[2961:2961:0324/003223.146477:3788269944:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000003f0\n[2961:2961:0324/003223.146580:3788270047: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[2961:2961:0324/003223.146872:3788270342:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000007e0\n[2961:2961:0324/003223.147927:3788271397:INFO:invalidation-client-impl_test.cc(477)] Reg manager state: { client_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_summary: { num_registrations: 1 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } }\n[ OK ] InvalidationClientImplTest.NoRegistrationSummary (5 ms)\n[19/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[2961:2961:0324/003223.148585:3788272055:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000640 with delay 0\n[2961:2961:0324/003223.148658:3788272126:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[2961:2961:0324/003223.148887:3788272355:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0\n[2961:2961:0324/003223.148931:3788272399:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000640\n[2961:2961:0324/003223.148976:3788272443:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510\n[2961:2961:0324/003223.149050:3788272517:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[2961:2961:0324/003223.149117:3788272599:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0\n[2961:2961:0324/003223.149182:3788272649:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490\n[2961:2961:0324/003223.149225:3788272694:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[2961:2961:0324/003223.149267:3788272735:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0\n[2961:2961:0324/003223.149309:3788272776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510\n[2961:2961:0324/003223.149345:3788272813:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[2961:2961:0324/003223.149390:3788272857:INFO:recurring-task.cc(55)] [Startup] Scheduling 2792 with a delay 0, Now = 210919424\n[2961:2961:0324/003223.149429:3788272896:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0\n[2961:2961:0324/003223.149472:3788272940:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490\n[2961:2961:0324/003223.149554:3788273021:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8673783965484074089\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[2961:2961:0324/003223.149598:3788273068:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424\n[2961:2961:0324/003223.149639:3788273107:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 500\n[2961:2961:0324/003223.149681:3788273148:INFO:recurring-task.cc(55)] [Retry] Scheduling 2792 with a delay 60000000, Now = 210919424\n[2961:2961:0324/003223.149721:3788273188:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000460 with delay 60000\n[2961:2961:0324/003223.149772:3788273239:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510\n[2961:2961:0324/003223.149812:3788273280:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.149863:3788273330:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[2961:2961:0324/003223.150003:3788273474: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: \"8673783965484074089\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[2961:2961:0324/003223.150155:3788273624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000510 with delay 0\n[2961:2961:0324/003223.150205:3788273673:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510\n[2961:2961:0324/003223.150333:3788273801:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8673783965484074089\" 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[2961:2961:0324/003223.150394:3788273862:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8673783965484074089\"\n[2961:2961:0324/003223.150439:3788273906:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[2961:2961:0324/003223.150485:3788273952:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[2961:2961:0324/003223.150535:3788274003:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003f0 with delay 1200000\n[2961:2961:0324/003223.150581:3788274049:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[2961:2961:0324/003223.150710:3788274177:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.150764:3788274232:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424\n[2961:2961:0324/003223.150807:3788274275:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000490 with delay 0\n[2961:2961:0324/003223.150868:3788274335: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[2961:2961:0324/003223.150919:3788274386:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000490\n[2961:2961:0324/003223.150992:3788274460:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0\n[2961:2961:0324/003223.151047:3788274514:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424\n[2961:2961:0324/003223.151093:3788274563:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000640 with delay 10000\n[2961:2961:0324/003223.151153:3788274621:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0\n[2961:2961:0324/003223.151191:3788274661:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[2961:2961:0324/003223.151478:3788274946:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000640\n[2961:2961:0324/003223.152724:3788276191:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000460\n[2961:2961:0324/003223.179419:3788302890:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7010000003f0\n[2961:2961:0324/003223.179525:3788302993:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.179597:3788303065:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[2961:2961:0324/003223.179645:3788303112:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[2961:2961:0324/003223.179860:3788303328: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[2961:2961:0324/003223.179924:3788303392:INFO:recurring-task.cc(55)] [Send-info] Scheduling 3464 with a delay 500000, Now = 1411419424\n[2961:2961:0324/003223.179968:3788303436:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000460 with delay 500\n[2961:2961:0324/003223.180025:3788303493:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[2961:2961:0324/003223.180068:3788303536:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000640 with delay 1200000\n[2961:2961:0324/003223.180131:3788303599:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000460\n[2961:2961:0324/003223.180174:3788303643:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.180254:3788303721:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[2961:2961:0324/003223.180294:3788303761:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[2961:2961:0324/003223.180543:3788304025:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: \"2\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } performance_counter: { name: \"SentMessageType.INITIALIZE\" value: 1 } performance_counter: { name: \"SentMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOKEN_CONTROL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ListenerEventType.REISSUE_REGISTRATIONS\" value: 1 } performance_counter: { name: \"ClientErrorType.PERSISTENT_READ_FAILURE\" value: 1 } server_registration_summary_requested: false } }\n[ OK ] InvalidationClientImplTest.Heartbeats (34 ms)\n[20/28] InvalidationClientImplTest.Heartbeats (34 ms)\n[ RUN ] ProtocolHandlerTest.TokenMissing\n[2966:2966:0324/003223.147024:3788270537:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000520 with delay 0\n[2966:2966:0324/003223.147164:3788270636:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000520\n[2966:2966:0324/003223.147540:3788271009: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[2966:2966:0324/003223.147618:3788271086:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2120 with a delay 500000, Now = 210919424\n[2966:2966:0324/003223.147679:3788271147:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 500\n[2966:2966:0324/003223.147734:3788271201:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000540\n[2966:2966:0324/003223.147835:3788271303:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[2966:2966:0324/003223.147882:3788271354:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (4 ms)\n[21/28] ProtocolHandlerTest.TokenMissing (4 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[2966:2966:0324/003223.148436:3788271910:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 0\n[2966:2966:0324/003223.148496:3788271964:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000540\n[2966:2966:0324/003223.148595:3788272067:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2408 with a delay 500000, Now = 210919424\n[2966:2966:0324/003223.148655:3788272130:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000520 with delay 500\n[2966:2966:0324/003223.148725:3788272194:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000520\n[2966:2966:0324/003223.148867:3788272340:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[2966:2966:0324/003223.148965:3788272435: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[2966:2966:0324/003223.149039:3788272509: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[2966:2966:0324/003223.149224:3788272693: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[2966:2966:0324/003223.149396:3788272868: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[2966:2966:0324/003223.149918:3788273386:INFO:protocol-handler.cc(139)] Incoming message: { }\n[2966:2966:0324/003223.149973:3788273443:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[2966:2966:0324/003223.150025:3788273500: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[2966:2966:0324/003223.150367:3788273841:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -964873096 with a delay 10000, Now = 0\n[2966:2966:0324/003223.150428:3788273898:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000390 with delay 10\n[2966:2966:0324/003223.150490:3788273957:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000390\n[2966:2966:0324/003223.150546:3788274017:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[2966:2966:0324/003223.150609:3788274080:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 10000\n[2966:2966:0324/003223.150661:3788274131:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003a0 with delay 60\n[2966:2966:0324/003223.150718:3788274185:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7010000003a0\n[2966:2966:0324/003223.150757:3788274226:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[2966:2966:0324/003223.150795:3788274263:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 70000\n[2966:2966:0324/003223.150833:3788274301:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x701000000390 with delay 60\n[2966:2966:0324/003223.150872:3788274339:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x701000000390\n[2966:2966:0324/003223.150914:3788274382:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[2966:2966:0324/003223.150951:3788274418:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 130000\n[2966:2966:0324/003223.150989:3788274456:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7010000003a0 with delay 60\n[2966:2966:0324/003223.151028:3788274495:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7010000003a0\n[2966:2966:0324/003223.151065:3788274532:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[2966:2966:0324/003223.151104:3788274570:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 190000\n[2966:2966:0324/003223.151151:3788274618:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x701000000390 with delay 60\n[2966:2966:0324/003223.151189:3788274662:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x701000000390\n[2966:2966:0324/003223.151232:3788274699:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[2966:2966:0324/003223.151266:3788274733:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 250000\n[2966:2966:0324/003223.151301:3788274768:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7010000003a0 with delay 60\n[2966:2966:0324/003223.151337:3788274804:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7010000003a0\n[2966:2966:0324/003223.151377:3788274846:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[2966:2966:0324/003223.151414:3788274880:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 310000\n[2966:2966:0324/003223.151448:3788274915:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x701000000390 with delay 60\n[2966:2966:0324/003223.151484:3788274951:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x701000000390\n[2966:2966:0324/003223.151518:3788274985:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[2966:2966:0324/003223.151551:3788275018:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 370000\n[2966:2966:0324/003223.151597:3788275064:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7010000003a0 with delay 60\n[2966:2966:0324/003223.151637:3788275105:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7010000003a0\n[2966:2966:0324/003223.151678:3788275152:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (2 ms)\n[24/28] RecurringTaskTest.PeriodicTask (2 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[2966:2966:0324/003223.153052:3788276520:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -964873280 with a delay 10000, Now = 0\n[2966:2966:0324/003223.153109:3788276588:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003a0 with delay 10\n[2966:2966:0324/003223.153172:3788276640:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003a0\n[2966:2966:0324/003223.153211:3788276678:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[2966:2966:0324/003223.153249:3788276716:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 50000, Now = 10000\n[2966:2966:0324/003223.153310:3788276778:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000390 with delay 50\n[2966:2966:0324/003223.153364:3788276831:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x701000000390\n[2966:2966:0324/003223.153404:3788276871:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[2966:2966:0324/003223.153443:3788276910:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 149000, Now = 60000\n[2966:2966:0324/003223.153486:3788276956:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7010000003a0 with delay 149\n[2966:2966:0324/003223.153535:3788277002:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7010000003a0\n[2966:2966:0324/003223.153595:3788277063:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[2966:2966:0324/003223.153635:3788277102:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 248000, Now = 210000\n[2966:2966:0324/003223.153692:3788277159:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x701000000390 with delay 248\n[2966:2966:0324/003223.153747:3788277214:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x701000000390\n[2966:2966:0324/003223.153791:3788277259:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[2966:2966:0324/003223.153842:3788277314:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 446000, Now = 460000\n[2966:2966:0324/003223.153893:3788277361:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7010000003a0 with delay 446\n[2966:2966:0324/003223.153948:3788277417:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7010000003a0\n[2966:2966:0324/003223.153993:3788277460:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[2966:2966:0324/003223.154031:3788277498:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 842000, Now = 910000\n[2966:2966:0324/003223.154078:3788277550:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x701000000390 with delay 842\n[2966:2966:0324/003223.154163:3788277631:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x701000000390\n[2966:2966:0324/003223.154203:3788277670:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[2966:2966:0324/003223.154238:3788277705:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 1040000, Now = 1760000\n[2966:2966:0324/003223.154273:3788277740:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7010000003a0 with delay 1040\n[2966:2966:0324/003223.154335:3788277802:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7010000003a0\n[2966:2966:0324/003223.154369:3788277836:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[2966:2966:0324/003223.154403:3788277870:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 1040000, Now = 2800000\n[2966:2966:0324/003223.154438:3788277904:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x701000000390 with delay 1040\n[2966:2966:0324/003223.154504:3788277971:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x701000000390\n[2966:2966:0324/003223.154538:3788278005:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[25/28] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[2966:2966:0324/003223.155886:3788279354:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -964873240 with a delay 10000, Now = 0\n[2966:2966:0324/003223.155937:3788279407:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000390 with delay 10\n[2966:2966:0324/003223.155991:3788279458:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000390\n[2966:2966:0324/003223.156028:3788279496:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[2966:2966:0324/003223.156081:3788279552:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -964873240 with a delay 10000, Now = 10000\n[2966:2966:0324/003223.156153:3788279626:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000390 with delay 10\n[2966:2966:0324/003223.156205:3788279673:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x701000000390\n[2966:2966:0324/003223.156245:3788279713:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (2 ms)\n[26/28] RecurringTaskTest.OneShotTask (2 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[2966:2966:0324/003223.157642:3788281111:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x701000000390 with delay 920\n[2966:2966:0324/003223.157722:3788281194:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000000390\n[2966:2966:0324/003223.158106:3788281582:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x701000000390 with delay 45000\n[2966:2966:0324/003223.159252:3788282722:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000000390\n[ OK ] ThrottleTest.ThrottlingScripted (2 ms)\n[27/28] ThrottleTest.ThrottlingScripted (2 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[2966:2966:0324/003223.159429:3788282899:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000390 with delay 990\n[2966:2966:0324/003223.159524:3788282992:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000000390\n[2966:2966:0324/003223.159572:3788283046:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.159647:3788283114:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x701000000390\n[2966:2966:0324/003223.159685:3788283151:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.159749:3788283216:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x701000000390\n[2966:2966:0324/003223.159786:3788283252:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.159850:3788283316:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x701000000390\n[2966:2966:0324/003223.159886:3788283352:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.159950:3788283416:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x701000000390\n[2966:2966:0324/003223.159986:3788283452:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.160050:3788283516:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x701000000390\n[2966:2966:0324/003223.160088:3788283557:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7010000003a0 with delay 54000\n[2966:2966:0324/003223.161840:3788285308:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.161887:3788285353:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.161959:3788285426:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.161997:3788285463:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.162061:3788285527:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.162100:3788285567:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.162180:3788285647:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.162218:3788285685:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.162282:3788285748:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.162318:3788285784:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.162388:3788285855:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.162426:3788285892:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.162491:3788285957:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.162530:3788285998:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x701000000390 with delay 54000\n[2966:2966:0324/003223.164229:3788287696:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x701000000390\n[2966:2966:0324/003223.164269:3788287736:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.164334:3788287800:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x701000000390\n[2966:2966:0324/003223.164371:3788287837:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.164435:3788287902:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x701000000390\n[2966:2966:0324/003223.164472:3788287938:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.164536:3788288014:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x701000000390\n[2966:2966:0324/003223.164594:3788288062:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.164661:3788288128:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x701000000390\n[2966:2966:0324/003223.164698:3788288164:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.164762:3788288228:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x701000000390\n[2966:2966:0324/003223.164798:3788288264:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.164862:3788288328:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x701000000390\n[2966:2966:0324/003223.164897:3788288364:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7010000003a0 with delay 54000\n[2966:2966:0324/003223.166607:3788290074:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.166647:3788290114:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.166713:3788290179:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.166749:3788290215:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.166818:3788290288:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.166859:3788290325:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.166929:3788290396:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.166966:3788290433:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.167031:3788290497:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.167067:3788290533:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.167143:3788290610:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.167182:3788290649:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7010000003a0 with delay 1000\n[2966:2966:0324/003223.167247:3788290713:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7010000003a0\n[2966:2966:0324/003223.167282:3788290749:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x701000000390 with delay 54000\n[2966:2966:0324/003223.168999:3788292466:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x701000000390\n[2966:2966:0324/003223.169042:3788292508:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.169110:3788292585:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x701000000390\n[2966:2966:0324/003223.169166:3788292633:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.169232:3788292698:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x701000000390\n[2966:2966:0324/003223.169268:3788292735:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.169333:3788292799:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x701000000390\n[2966:2966:0324/003223.169368:3788292835:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.169432:3788292899:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x701000000390\n[2966:2966:0324/003223.169468:3788292935:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.169532:3788292998:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x701000000390\n[2966:2966:0324/003223.169568:3788293034:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x701000000390 with delay 1000\n[2966:2966:0324/003223.169638:3788293105:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x701000000390\n[2966:2966:0324/003223.169674:3788293141:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7010000003a0 with delay 54000\n[2966:2966:0324/003223.171394:3788294861:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7010000003a0\n[ OK ] ThrottleTest.ThrottlingStorm (12 ms)\n[28/28] ThrottleTest.ThrottlingStorm (12 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "0530a88f9ab9f74f3b10b63775f60f1d114abc7b", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43c76ec9ef089a11", "server_versions": [ "4216-cf4a3cd" ], "started_ts": "2019-03-24T07:32:17.204477", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux ChromiumOS MSan Tests", "buildnumber:11978", "cpu:x86-64", "data:dfdb629dadbcb4a99caf2a4daed54eba122268f7", "gpu:none", "master:chromium.memory", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "pool:Chrome", "priority:25", "project:chromium", "purpose:CI", "purpose:luci", "purpose:post-commit", "service_account:none", "slavename:swarm2374-c4", "spec_name:chromium.ci:Linux ChromiumOS MSan Tests", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:d172b3da50f79bdc0892909417b8871a46e09913", "user:None" ], "task_id": "43c9b6eda3d20c10" } ] }