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

{ "shards": [ { "bot_dimensions": [ { "key": "caches", "value": [ "swarming_module_cache_vpython" ] }, { "key": "cores", "value": [ "8" ] }, { "key": "cpu", "value": [ "x86", "x86-64", "x86-64-Broadwell_GCE", "x86-64-avx2" ] }, { "key": "gce", "value": [ "1" ] }, { "key": "gpu", "value": [ "none" ] }, { "key": "id", "value": [ "gce-trusty-e833d7b0-us-east1-b-cfzn" ] }, { "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-east", "us-east1", "us-east1-b" ] } ], "bot_id": "gce-trusty-e833d7b0-us-east1-b-cfzn", "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-24T06:39:43.980999", "cost_saved_usd": 0.000847836188572797, "created_ts": "2019-03-24T18:32:41.803427", "deduped_from": "43c73e9235ff3311", "duration": 1.9269640445709229, "modified_ts": "2019-03-24T18:32:41.838212", "name": "cacheinvalidation_unittests/Ubuntu-14.04/8742049007/Linux TSan Tests/35963", "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 NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\n TSAN_OPTIONS=symbolize=1 external_symbolizer_path=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer handle_abort=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioigtFMv/output.json --no-sandbox\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[5018:5018:0323/233941.705884:1674885412:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b60 with delay 0\n[5018:5018:0323/233941.706257:1674885785:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b60\n[5018:5018:0323/233941.706608:1674886134: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[5018:5018:0323/233941.706717:1674886244:INFO:recurring-task.cc(55)] [Startup] Scheduling 7112 with a delay 500000, Now = 210919424\n[5018:5018:0323/233941.706805:1674886330:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000bf0 with delay 500\n[5018:5018:0323/233941.706886:1674886411:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000bf0\n[5018:5018:0323/233941.707296:1674886822:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } initialize_message: { client_type: 2 nonce: \"unit-test-nonce\" application_client_id: { client_type: 2 client_name: \"unit-test-client-id\" } digest_serialization_type: BYTE_BASED } }\n[ OK ] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[1/28] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[5018:5018:0323/233941.709460:1674888987:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"fake nonce\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } token_control_message: { new_token: \"new token\" } }\n[ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[5018:5018:0323/233941.710243:1674889774:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0\n[5018:5018:0323/233941.710340:1674889865:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b20 with delay 0\n[5018:5018:0323/233941.710417:1674889941:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000aa0 with delay 0\n[5018:5018:0323/233941.710506:1674890034:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ae0 with delay 0\n[5018:5018:0323/233941.710578:1674890101:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a90 with delay 0\n[5018:5018:0323/233941.710660:1674890187:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[5018:5018:0323/233941.711084:1674890611:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0\n[5018:5018:0323/233941.711320:1674890846: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[5018:5018:0323/233941.711418:1674890943:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7400 with a delay 500000, Now = 210919424\n[5018:5018:0323/233941.711507:1674891032:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c40 with delay 500\n[5018:5018:0323/233941.711580:1674891105:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b20\n[5018:5018:0323/233941.711658:1674891182:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000aa0\n[5018:5018:0323/233941.711743:1674891268:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ae0\n[5018:5018:0323/233941.711813:1674891336:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000a90\n[5018:5018:0323/233941.711882:1674891405:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[5018:5018:0323/233941.711996:1674891526:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[5018:5018:0323/233941.712088:1674891613:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c40\n[5018:5018:0323/233941.712302:1674891828:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[5018:5018:0323/233941.713546:1674893073: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[5018:5018:0323/233941.716251:1674895778: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[5018:5018:0323/233941.717315:1674896843: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[5018:5018:0323/233941.717518:1674897045: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[5018:5018:0323/233941.717726:1674897252: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[5018:5018:0323/233941.717926:1674897452: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 (2 ms)\n[5/28] ProtocolHandlerTest.InvalidInboundMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[5018:5018:0323/233941.718909:1674898437: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[5018:5018:0323/233941.719169:1674898698:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[6/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[5018:5018:0323/233941.720546:1674900072: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[5018:5018:0323/233941.721507:1674901035: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[5018:5018:0323/233941.721606:1674901132:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a20 with delay 0\n[5018:5018:0323/233941.721679:1674901219:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000a20\n[5018:5018:0323/233941.721857:1674901386: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[5018:5018:0323/233941.721958:1674901486:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7784 with a delay 500000, Now = 210919424\n[5018:5018:0323/233941.722039:1674901565:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a30 with delay 500\n[5018:5018:0323/233941.722119:1674901650:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a30\n[5018:5018:0323/233941.722197:1674901722:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (21 ms)\n[8/28] ProtocolHandlerTest.ConfigMessage (21 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[5018:5018:0323/233941.742315:1674921844:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.ErrorMessage (1 ms)\n[9/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[5018:5018:0323/233941.743308:1674922837: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 ] ProtocolHandlerTest.TokenMissing\n[5019:5019:0323/233941.727547:1674907077:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b60 with delay 0\n[5019:5019:0323/233941.727660:1674907187:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b60\n[5019:5019:0323/233941.728038:1674907565: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[5019:5019:0323/233941.728160:1674907687:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7112 with a delay 500000, Now = 210919424\n[5019:5019:0323/233941.728235:1674907758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b70 with delay 500\n[5019:5019:0323/233941.728326:1674907850:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b70\n[5019:5019:0323/233941.728488:1674908040:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[5019:5019:0323/233941.728602:1674908128:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\n[11/28] ProtocolHandlerTest.TokenMissing (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[5019:5019:0323/233941.729493:1674909023:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b70 with delay 0\n[5019:5019:0323/233941.729584:1674909117:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b70\n[5019:5019:0323/233941.729683:1674909227:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7400 with a delay 500000, Now = 210919424\n[5019:5019:0323/233941.729787:1674909313:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b60 with delay 500\n[5019:5019:0323/233941.729869:1674909395:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b60\n[5019:5019:0323/233941.730074:1674910428:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[5019:5019:0323/233941.731031:1674910556: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[5019:5019:0323/233941.731168:1674910692: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[5019:5019:0323/233941.731480:1674911006: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[5019:5019:0323/233941.731824:1674911352: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 (3 ms)\n[12/28] ProtocolHandlerTest.InvalidOutboundMessage (3 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[5019:5019:0323/233941.732695:1674912235:INFO:protocol-handler.cc(139)] Incoming message: { }\n[5019:5019:0323/233941.732803:1674912329:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[5019:5019:0323/233941.732890:1674912415:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[13/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[5019:5019:0323/233941.733405:1674912932:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 493424168 with a delay 10000, Now = 0\n[5019:5019:0323/233941.733487:1674913012:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009d0 with delay 10\n[5019:5019:0323/233941.733592:1674913117:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.733671:1674913196:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[5019:5019:0323/233941.733779:1674913305:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 60000, Now = 10000\n[5019:5019:0323/233941.733855:1674913381:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009e0 with delay 60\n[5019:5019:0323/233941.733931:1674913454:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.733995:1674913520:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[5019:5019:0323/233941.734063:1674913588:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 60000, Now = 70000\n[5019:5019:0323/233941.734134:1674913659:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7b04000009d0 with delay 60\n[5019:5019:0323/233941.734203:1674913725:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.734265:1674913791:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[5019:5019:0323/233941.734334:1674913857:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 60000, Now = 130000\n[5019:5019:0323/233941.734399:1674913923:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7b04000009e0 with delay 60\n[5019:5019:0323/233941.734465:1674913988:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.734528:1674914051:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[5019:5019:0323/233941.734593:1674914117:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 60000, Now = 190000\n[5019:5019:0323/233941.734658:1674914182:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7b04000009d0 with delay 60\n[5019:5019:0323/233941.734743:1674914267:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.734812:1674914335:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[5019:5019:0323/233941.734877:1674914401:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 60000, Now = 250000\n[5019:5019:0323/233941.734942:1674914465:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7b04000009e0 with delay 60\n[5019:5019:0323/233941.735005:1674914529:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.735068:1674914591:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[5019:5019:0323/233941.735132:1674914655:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 60000, Now = 310000\n[5019:5019:0323/233941.735223:1674914747:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7b04000009d0 with delay 60\n[5019:5019:0323/233941.735290:1674914813:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.735353:1674914876:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[5019:5019:0323/233941.735417:1674914941:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 60000, Now = 370000\n[5019:5019:0323/233941.735489:1674915013:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7b04000009e0 with delay 60\n[5019:5019:0323/233941.735575:1674915099:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.735650:1674915174:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (3 ms)\n[14/28] RecurringTaskTest.PeriodicTask (3 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[5019:5019:0323/233941.736399:1674915926:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 493424168 with a delay 10000, Now = 0\n[5019:5019:0323/233941.736486:1674916035:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009e0 with delay 10\n[5019:5019:0323/233941.736584:1674916109:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.736679:1674916219:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[5019:5019:0323/233941.736769:1674916299:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 50000, Now = 10000\n[5019:5019:0323/233941.736851:1674916376:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009d0 with delay 50\n[5019:5019:0323/233941.736930:1674916455:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.736999:1674916525:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[5019:5019:0323/233941.737078:1674916602:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 149000, Now = 60000\n[5019:5019:0323/233941.737149:1674916674:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7b04000009e0 with delay 149\n[5019:5019:0323/233941.737235:1674916758:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.737302:1674916826:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[5019:5019:0323/233941.737382:1674916907:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 248000, Now = 210000\n[5019:5019:0323/233941.737457:1674916981:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7b04000009d0 with delay 248\n[5019:5019:0323/233941.737539:1674917063:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.737605:1674917134:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[5019:5019:0323/233941.737680:1674917224:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 446000, Now = 460000\n[5019:5019:0323/233941.737776:1674917301:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7b04000009e0 with delay 446\n[5019:5019:0323/233941.737851:1674917375:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.737919:1674917444:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[5019:5019:0323/233941.737988:1674917512:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 842000, Now = 910000\n[5019:5019:0323/233941.738064:1674917589:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7b04000009d0 with delay 842\n[5019:5019:0323/233941.738144:1674917668:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.738208:1674917732:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[5019:5019:0323/233941.738275:1674917799:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 1040000, Now = 1760000\n[5019:5019:0323/233941.738341:1674917865:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7b04000009e0 with delay 1040\n[5019:5019:0323/233941.738418:1674917941:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.738480:1674918004:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[5019:5019:0323/233941.738545:1674918069:INFO:recurring-task.cc(55)] [Retry] Scheduling 493424168 with a delay 1040000, Now = 2800000\n[5019:5019:0323/233941.738610:1674918134:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7b04000009d0 with delay 1040\n[5019:5019:0323/233941.738691:1674918231:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.738777:1674918302:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (4 ms)\n[15/28] RecurringTaskTest.ExponentialBackoffTask (4 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[5019:5019:0323/233941.740296:1674919824:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 493424096 with a delay 10000, Now = 0\n[5019:5019:0323/233941.740377:1674919903:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009d0 with delay 10\n[5019:5019:0323/233941.740474:1674919998:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.740756:1674920292:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[5019:5019:0323/233941.740862:1674920393:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 493424096 with a delay 10000, Now = 10000\n[5019:5019:0323/233941.740968:1674920495:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009d0 with delay 10\n[5019:5019:0323/233941.741054:1674920580:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.741129:1674920662:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (1 ms)\n[16/28] RecurringTaskTest.OneShotTask (1 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[5019:5019:0323/233941.742158:1674921689:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7b04000009d0 with delay 920\n[5019:5019:0323/233941.742262:1674921788:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.742472:1674922021:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7b04000009d0 with delay 45000\n[5019:5019:0323/233941.743198:1674922773:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b04000009d0\n[ OK ] ThrottleTest.ThrottlingScripted (1 ms)\n[17/28] ThrottleTest.ThrottlingScripted (1 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[5019:5019:0323/233941.743639:1674923168:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009d0 with delay 990\n[5019:5019:0323/233941.743766:1674923295:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.743851:1674923378:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.743942:1674923472:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.744022:1674923545:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.744106:1674923631:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.744182:1674923707:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.744271:1674923799:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.744346:1674923869:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.744428:1674923950:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.744533:1674924058:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.744630:1674924156:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.744729:1674924261:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7b04000009e0 with delay 54000\n[5019:5019:0323/233941.746313:1674925838:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.746398:1674925923:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.746502:1674926025:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.746572:1674926095:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.746655:1674926178:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.746737:1674926260:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.746819:1674926342:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.746886:1674926410:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.746975:1674926498:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.747043:1674926566:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.747125:1674926648:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.747192:1674926716:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.747274:1674926798:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.747343:1674926867:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7b04000009d0 with delay 54000\n[5019:5019:0323/233941.748421:1674927945:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.748524:1674928049:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.748615:1674928139:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.748685:1674928226:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.748787:1674928310:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.748856:1674928380:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.748939:1674928467:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.749012:1674928536:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.749095:1674928618:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.749163:1674928687:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.749245:1674928768:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.749313:1674928836:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.749393:1674928916:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.749462:1674928986:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7b04000009e0 with delay 54000\n[5019:5019:0323/233941.750955:1674930481:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.751038:1674930562:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.751123:1674930647:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.751193:1674930717:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.751282:1674930805:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.751352:1674930875:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.751443:1674930970:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.751518:1674931042:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.751602:1674931125:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.751670:1674931193:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.751768:1674931291:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.751836:1674931360:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7b04000009e0 with delay 1000\n[5019:5019:0323/233941.751918:1674931441:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7b04000009e0\n[5019:5019:0323/233941.751991:1674931515:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7b04000009d0 with delay 54000\n[5019:5019:0323/233941.753097:1674932622:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.753181:1674932706:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.753266:1674932790:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.753342:1674932866:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.753426:1674932948:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.753498:1674933021:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.753580:1674933103:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.753647:1674933171:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.753744:1674933267:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.753812:1674933335:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.753893:1674933417:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.753966:1674933490:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7b04000009d0 with delay 1000\n[5019:5019:0323/233941.754047:1674933575:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7b04000009d0\n[5019:5019:0323/233941.754119:1674933643:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7b04000009e0 with delay 54000\n[5019:5019:0323/233941.755444:1674934973:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7b04000009e0\n[ OK ] ThrottleTest.ThrottlingStorm (12 ms)\n[18/28] ThrottleTest.ThrottlingStorm (12 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[5016:5016:0323/233941.691359:1674870889:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c60 with delay 0\n[5016:5016:0323/233941.691691:1674871232:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.692136:1674871663:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e30 with delay 0\n[5016:5016:0323/233941.692217:1674871741:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c60\n[5016:5016:0323/233941.692294:1674871818:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e30\n[5016:5016:0323/233941.692437:1674871962:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.692597:1674872122:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e80 with delay 0\n[5016:5016:0323/233941.692685:1674872223:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e80\n[5016:5016:0323/233941.692771:1674872296:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.692847:1674872371:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e30 with delay 0\n[5016:5016:0323/233941.692916:1674872441:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e30\n[5016:5016:0323/233941.692994:1674872521:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.693074:1674872599:INFO:recurring-task.cc(55)] [Startup] Scheduling 7112 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.693144:1674872668:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e80 with delay 0\n[5016:5016:0323/233941.693214:1674872739:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e80\n[5016:5016:0323/233941.693368:1674872893:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-8352773372948132541\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.693877:1674873401:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7496 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.693950:1674873474:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e30 with delay 500\n[5016:5016:0323/233941.694021:1674873546:INFO:recurring-task.cc(55)] [Retry] Scheduling 7112 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.694091:1674873615:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000df0 with delay 60000\n[5016:5016:0323/233941.694166:1674873690:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e30\n[5016:5016:0323/233941.694233:1674873759:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.694357:1674873882:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.694662:1674874188: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: \"-8352773372948132541\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.694907:1674874433:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e30 with delay 0\n[5016:5016:0323/233941.694981:1674874509:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e30\n[5016:5016:0323/233941.695287:1674874813:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-8352773372948132541\" 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[5016:5016:0323/233941.695395:1674874921:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-8352773372948132541\"\n[5016:5016:0323/233941.695473:1674875003:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.695558:1674875083:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.695628:1674875153:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e70 with delay 1200000\n[5016:5016:0323/233941.695718:1674875242:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.695959:1674875484:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.696039:1674875564:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.696112:1674875636:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e80 with delay 0\n[5016:5016:0323/233941.696229:1674875754: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[5016:5016:0323/233941.696312:1674875837:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e80\n[5016:5016:0323/233941.696449:1674875974:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ea0 with delay 0\n[5016:5016:0323/233941.696557:1674876082:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.696628:1674876153:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c60 with delay 10000\n[5016:5016:0323/233941.696715:1674876240:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ea0\n[5016:5016:0323/233941.696783:1674876308:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[ OK ] InvalidationClientImplTest.Start (7 ms)\n[19/28] InvalidationClientImplTest.Start (7 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[5016:5016:0323/233941.697838:1674877368:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0\n[5016:5016:0323/233941.697965:1674877491:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)\n[20/28] InvalidationClientImplTest.GenerateNonce (1 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[5016:5016:0323/233941.698896:1674878422:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e60 with delay 0\n[5016:5016:0323/233941.699010:1674878537:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.699456:1674878983:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ec0 with delay 0\n[5016:5016:0323/233941.699547:1674879071:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e60\n[5016:5016:0323/233941.699623:1674879147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ec0\n[5016:5016:0323/233941.699776:1674879305:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.699890:1674879414:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[5016:5016:0323/233941.699965:1674879490:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.700035:1674879561:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.700110:1674879635:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ec0 with delay 0\n[5016:5016:0323/233941.700184:1674879708:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ec0\n[5016:5016:0323/233941.700252:1674879776:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.700328:1674879853:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.700397:1674879921:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[5016:5016:0323/233941.700469:1674879998:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.700636:1674880162:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-8456675768821315228\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.700737:1674880262:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7112 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.700810:1674880335:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ec0 with delay 500\n[5016:5016:0323/233941.700885:1674880410:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.700954:1674880479:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ee0 with delay 60000\n[5016:5016:0323/233941.701035:1674880558:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ec0\n[5016:5016:0323/233941.701103:1674880628:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.701186:1674880710:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.701476:1674881010: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: \"-8456675768821315228\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.701669:1674881194:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ec0 with delay 0\n[5016:5016:0323/233941.701759:1674881284:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ec0\n[5016:5016:0323/233941.702020:1674881547:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-8456675768821315228\" 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[5016:5016:0323/233941.702121:1674881647:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-8456675768821315228\"\n[5016:5016:0323/233941.702204:1674881730:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.702282:1674881806:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.702352:1674881877:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ef0 with delay 1200000\n[5016:5016:0323/233941.702429:1674881954:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.702657:1674882182:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.702747:1674882272:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.702829:1674882354:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f00 with delay 0\n[5016:5016:0323/233941.702942:1674882467: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[5016:5016:0323/233941.703033:1674882559:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.703171:1674882697:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 0\n[5016:5016:0323/233941.703252:1674882778:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.703323:1674882849:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e60 with delay 10000\n[5016:5016:0323/233941.703395:1674882920:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f20\n[5016:5016:0323/233941.703466:1674882998:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.703574:1674883099:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f20 with delay 0\n[5016:5016:0323/233941.703645:1674883171:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f20\n[5016:5016:0323/233941.703758:1674883283:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[5016:5016:0323/233941.703851:1674883376:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[5016:5016:0323/233941.703942:1674883465:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[5016:5016:0323/233941.704098:1674883624:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7112 with a delay 500000, Now = 211469424\n[5016:5016:0323/233941.704174:1674883698:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f00 with delay 500\n[5016:5016:0323/233941.704247:1674883773:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7784 with a delay 60000000, Now = 211469424\n[5016:5016:0323/233941.704318:1674883845:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f10 with delay 60000\n[5016:5016:0323/233941.704402:1674883926:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.704472:1674884016:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.705009:1674884535:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.705087:1674884611:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[5016:5016:0323/233941.705461:1674884995: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[5016:5016:0323/233941.705624:1674885150:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.705770:1674885295:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400000f00 with delay 0\n[5016:5016:0323/233941.705843:1674885367:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.706342:1674885868: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[5016:5016:0323/233941.706515:1674886041: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[5016:5016:0323/233941.706715:1674886241:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[5016:5016:0323/233941.706921:1674886446:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[5016:5016:0323/233941.707111:1674886636:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[5016:5016:0323/233941.707350:1674886874:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e60\n[ OK ] InvalidationClientImplTest.Register (10 ms)\n[21/28] InvalidationClientImplTest.Register (10 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[5016:5016:0323/233941.708878:1674888405:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000da0 with delay 0\n[5016:5016:0323/233941.708994:1674888521:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.709503:1674889035:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 0\n[5016:5016:0323/233941.709588:1674889112:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000da0\n[5016:5016:0323/233941.709656:1674889179:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c10\n[5016:5016:0323/233941.709812:1674889339:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.709926:1674889452:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0\n[5016:5016:0323/233941.710008:1674889532:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20\n[5016:5016:0323/233941.710077:1674889603:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.710150:1674889675:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 0\n[5016:5016:0323/233941.710222:1674889746:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c10\n[5016:5016:0323/233941.710290:1674889815:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.710372:1674889897:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.710445:1674889971:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0\n[5016:5016:0323/233941.710522:1674890046:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20\n[5016:5016:0323/233941.710665:1674890190:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"7233089895789358392\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.710759:1674890285:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.710832:1674890357:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 500\n[5016:5016:0323/233941.710906:1674890432:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.710976:1674890506:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b80 with delay 60000\n[5016:5016:0323/233941.711057:1674890582:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c10\n[5016:5016:0323/233941.711126:1674890651:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.711212:1674890736:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.711506:1674891031: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: \"7233089895789358392\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.711688:1674891227:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c10 with delay 0\n[5016:5016:0323/233941.711779:1674891305:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c10\n[5016:5016:0323/233941.712043:1674891569:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"7233089895789358392\" 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[5016:5016:0323/233941.712144:1674891670:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"7233089895789358392\"\n[5016:5016:0323/233941.712221:1674891748:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.712297:1674891823:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.712368:1674891897:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ec0 with delay 1200000\n[5016:5016:0323/233941.712445:1674891970:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.712691:1674892232:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.712785:1674892310:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.712859:1674892385:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 0\n[5016:5016:0323/233941.712974:1674892502: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[5016:5016:0323/233941.713064:1674892589:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f20\n[5016:5016:0323/233941.713192:1674892718:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f50 with delay 0\n[5016:5016:0323/233941.713275:1674892801:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.713346:1674892870:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000da0 with delay 10000\n[5016:5016:0323/233941.713419:1674892943:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f50\n[5016:5016:0323/233941.713492:1674893016:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.713575:1674893100:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.713695:1674893234:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f50 with delay 0\n[5016:5016:0323/233941.713783:1674893308:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f50\n[5016:5016:0323/233941.714643:1674894169: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[5016:5016:0323/233941.714815:1674894339: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[5016:5016:0323/233941.714974:1674894503: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[5016:5016:0323/233941.715193:1674894719: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[5016:5016:0323/233941.715387:1674894912: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[5016:5016:0323/233941.715542:1674895068:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f50 with delay 0\n[5016:5016:0323/233941.715616:1674895139:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f20 with delay 0\n[5016:5016:0323/233941.715687:1674895223:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f30 with delay 0\n[5016:5016:0323/233941.715767:1674895292:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f50\n[5016:5016:0323/233941.715861:1674895388:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7976 with a delay 500000, Now = 211519424\n[5016:5016:0323/233941.715934:1674895458:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000c10 with delay 500\n[5016:5016:0323/233941.716030:1674895566:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f20\n[5016:5016:0323/233941.716141:1674895665:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f30\n[5016:5016:0323/233941.716226:1674895749:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7b0400000c10\n[5016:5016:0323/233941.716300:1674895826:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.716397:1674895922:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.716470:1674896134:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[5016:5016:0323/233941.717068:1674896594: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 (9 ms)\n[22/28] InvalidationClientImplTest.Invalidations (9 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[5016:5016:0323/233941.718171:1674897699:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e90 with delay 0\n[5016:5016:0323/233941.718284:1674897809:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.718660:1674898188:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[5016:5016:0323/233941.718748:1674898272:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e90\n[5016:5016:0323/233941.718814:1674898337:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.718954:1674898479:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.719065:1674898591:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[5016:5016:0323/233941.719141:1674898666:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.719210:1674898737:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.719284:1674898809:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[5016:5016:0323/233941.719353:1674898876:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.719419:1674898943:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.719506:1674899031:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.719579:1674899104:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 0\n[5016:5016:0323/233941.719651:1674899175:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.719801:1674899327:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-9135236090806365477\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.719883:1674899409:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.719952:1674899477:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 500\n[5016:5016:0323/233941.720028:1674899553:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.720096:1674899620:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d20 with delay 60000\n[5016:5016:0323/233941.720179:1674899704:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.720248:1674899774:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.720331:1674899855:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.720637:1674900163: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: \"-9135236090806365477\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.720832:1674900358:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000cf0 with delay 0\n[5016:5016:0323/233941.720912:1674900437:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.721178:1674900704:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-9135236090806365477\" 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[5016:5016:0323/233941.721279:1674900804:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-9135236090806365477\"\n[5016:5016:0323/233941.721355:1674900881:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.721432:1674900958:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.721510:1674901034:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000be0 with delay 1200000\n[5016:5016:0323/233941.721586:1674901111:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.721826:1674901352:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.721904:1674901428:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.721977:1674901504:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f00 with delay 0\n[5016:5016:0323/233941.722091:1674901615: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[5016:5016:0323/233941.722174:1674901699:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.722302:1674901827:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c00 with delay 0\n[5016:5016:0323/233941.722382:1674901908:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.722453:1674901977:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e90 with delay 10000\n[5016:5016:0323/233941.722531:1674902055:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c00\n[5016:5016:0323/233941.722597:1674902122:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.722681:1674902216:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.722787:1674902312:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000c00 with delay 0\n[5016:5016:0323/233941.722863:1674902388:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000c00\n[5016:5016:0323/233941.723136:1674902662: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[5016:5016:0323/233941.723275:1674902800: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[5016:5016:0323/233941.723359:1674902884:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[5016:5016:0323/233941.723432:1674902956:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 8456 with a delay 500000, Now = 211469424\n[5016:5016:0323/233941.723519:1674903044:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f00 with delay 500\n[5016:5016:0323/233941.723595:1674903119:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[5016:5016:0323/233941.724055:1674903582: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[5016:5016:0323/233941.724171:1674903697:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f00\n[5016:5016:0323/233941.724246:1674903771:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.724362:1674903888:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.724435:1674903960:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[5016:5016:0323/233941.726049:1674905579: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[5016:5016:0323/233941.726342:1674905867:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e90\n[ OK ] InvalidationClientImplTest.ServerRequests (10 ms)\n[23/28] InvalidationClientImplTest.ServerRequests (10 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[5016:5016:0323/233941.727857:1674907384:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 0\n[5016:5016:0323/233941.727971:1674907499:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.728398:1674907925:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[5016:5016:0323/233941.728473:1674908018:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b30\n[5016:5016:0323/233941.728564:1674908088:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.728721:1674908247:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.728838:1674908363:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ac0 with delay 0\n[5016:5016:0323/233941.728924:1674908449:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ac0\n[5016:5016:0323/233941.728997:1674908522:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.729071:1674908597:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 0\n[5016:5016:0323/233941.729145:1674908670:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.729214:1674908738:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.729288:1674908813:INFO:recurring-task.cc(55)] [Startup] Scheduling 7976 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.729362:1674908886:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ac0 with delay 0\n[5016:5016:0323/233941.729431:1674908955:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ac0\n[5016:5016:0323/233941.729579:1674909104:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"7830851383325257395\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.729657:1674909183:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7592 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.729745:1674909270:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000cf0 with delay 500\n[5016:5016:0323/233941.729815:1674909341:INFO:recurring-task.cc(55)] [Retry] Scheduling 7976 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.729890:1674909414:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ab0 with delay 60000\n[5016:5016:0323/233941.729966:1674909491:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.730040:1674909565:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.730124:1674909649:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.730422:1674909948: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: \"7830851383325257395\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.730608:1674910133:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000cf0 with delay 0\n[5016:5016:0323/233941.730681:1674910222:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000cf0\n[5016:5016:0323/233941.730960:1674910487:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"7830851383325257395\" 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[5016:5016:0323/233941.731064:1674910589:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"7830851383325257395\"\n[5016:5016:0323/233941.731142:1674910667:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.731218:1674910743:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.731292:1674910817:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b10 with delay 1200000\n[5016:5016:0323/233941.731366:1674910890:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.731599:1674911125:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.731678:1674911216:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.731766:1674911291:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ac0 with delay 0\n[5016:5016:0323/233941.731880:1674911404: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[5016:5016:0323/233941.731967:1674911496:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ac0\n[5016:5016:0323/233941.732099:1674911625:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000009c0 with delay 0\n[5016:5016:0323/233941.732181:1674911707:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.732252:1674911780:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b30 with delay 10000\n[5016:5016:0323/233941.732326:1674911850:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000009c0\n[5016:5016:0323/233941.732393:1674911917:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.732476:1674912020:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.732594:1674912119:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b04000009c0 with delay 0\n[5016:5016:0323/233941.732664:1674912189:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b04000009c0\n[5016:5016:0323/233941.732922:1674912447: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[5016:5016:0323/233941.733059:1674912585: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[5016:5016:0323/233941.733140:1674912665:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[5016:5016:0323/233941.733398:1674912928:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000b30\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (7 ms)\n[24/28] InvalidationClientImplTest.IncomingErrorMessage (7 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[5016:5016:0323/233941.735321:1674914849:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d70 with delay 0\n[5016:5016:0323/233941.735436:1674914962:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.735941:1674915468:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0\n[5016:5016:0323/233941.736018:1674915542:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000d70\n[5016:5016:0323/233941.736086:1674915609:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e50\n[5016:5016:0323/233941.736229:1674915754:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.736338:1674915863:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f30 with delay 0\n[5016:5016:0323/233941.736416:1674915940:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f30\n[5016:5016:0323/233941.736484:1674916030:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.736580:1674916104:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0\n[5016:5016:0323/233941.736657:1674916181:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e50\n[5016:5016:0323/233941.736739:1674916264:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.736815:1674916339:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.736886:1674916411:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f30 with delay 0\n[5016:5016:0323/233941.736956:1674916481:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f30\n[5016:5016:0323/233941.737102:1674916628:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1734954820780394602\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.737188:1674916717:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.737264:1674916788:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 500\n[5016:5016:0323/233941.737334:1674916859:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.737403:1674916930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 60000\n[5016:5016:0323/233941.737482:1674917011:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e50\n[5016:5016:0323/233941.737555:1674917080:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.737641:1674917166:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.737947:1674917472: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: \"1734954820780394602\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.738132:1674917658:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e50 with delay 0\n[5016:5016:0323/233941.738207:1674917733:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e50\n[5016:5016:0323/233941.738462:1674917993:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1734954820780394602\" 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[5016:5016:0323/233941.738577:1674918103:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1734954820780394602\"\n[5016:5016:0323/233941.738669:1674918221:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.738785:1674918309:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.738860:1674918385:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 1200000\n[5016:5016:0323/233941.738934:1674918459:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.739159:1674918685:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.739236:1674918761:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.739316:1674918840:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f30 with delay 0\n[5016:5016:0323/233941.739429:1674918954: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[5016:5016:0323/233941.739521:1674919046:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f30\n[5016:5016:0323/233941.739655:1674919180:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f40 with delay 0\n[5016:5016:0323/233941.739749:1674919275:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.739819:1674919345:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000d70 with delay 10000\n[5016:5016:0323/233941.739893:1674919418:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f40\n[5016:5016:0323/233941.739961:1674919485:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.740045:1674919571:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f40 with delay 0\n[5016:5016:0323/233941.740118:1674919644:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f40\n[5016:5016:0323/233941.740216:1674919741:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[5016:5016:0323/233941.740334:1674919859:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7976 with a delay 500000, Now = 211469424\n[5016:5016:0323/233941.740407:1674919932:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f30 with delay 500\n[5016:5016:0323/233941.740481:1674920026:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7112 with a delay 60000000, Now = 211469424\n[5016:5016:0323/233941.740577:1674920102:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f50 with delay 60000\n[5016:5016:0323/233941.740657:1674920182:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f30\n[5016:5016:0323/233941.740745:1674920269:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.740830:1674920355:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.740901:1674920426:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[5016:5016:0323/233941.741198:1674920723: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[5016:5016:0323/233941.741342:1674920867:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.741440:1674920966:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400000f30 with delay 0\n[5016:5016:0323/233941.741524:1674921050:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f30\n[5016:5016:0323/233941.741778:1674921304: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[5016:5016:0323/233941.741911:1674921437: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[5016:5016:0323/233941.741995:1674921520:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[5016:5016:0323/233941.742149:1674921674:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[5016:5016:0323/233941.742400:1674921926:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000d70\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (9 ms)\n[25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (9 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[5016:5016:0323/233941.744268:1674923796:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c00 with delay 0\n[5016:5016:0323/233941.744382:1674923908:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.744785:1674924311:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 0\n[5016:5016:0323/233941.744864:1674924388:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c00\n[5016:5016:0323/233941.744931:1674924454:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b30\n[5016:5016:0323/233941.745074:1674924600:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.745190:1674924715:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e00 with delay 0\n[5016:5016:0323/233941.745265:1674924790:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e00\n[5016:5016:0323/233941.745334:1674924858:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.745407:1674924932:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 0\n[5016:5016:0323/233941.745477:1674925006:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b30\n[5016:5016:0323/233941.745551:1674925076:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.745632:1674925157:INFO:recurring-task.cc(55)] [Startup] Scheduling 7880 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.745714:1674925239:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e00 with delay 0\n[5016:5016:0323/233941.745785:1674925308:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e00\n[5016:5016:0323/233941.745927:1674925453:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"281194164665261979\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.746015:1674925540:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7688 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.746085:1674925610:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b30 with delay 500\n[5016:5016:0323/233941.746157:1674925683:INFO:recurring-task.cc(55)] [Retry] Scheduling 7880 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.746227:1674925752:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c30 with delay 60000\n[5016:5016:0323/233941.746302:1674925825:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b30\n[5016:5016:0323/233941.746371:1674925895:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.746454:1674925978:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.746757:1674926283: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: \"281194164665261979\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.746938:1674926465:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b30 with delay 0\n[5016:5016:0323/233941.747018:1674926543:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b30\n[5016:5016:0323/233941.747302:1674926828:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"281194164665261979\" 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[5016:5016:0323/233941.747402:1674926929:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"281194164665261979\"\n[5016:5016:0323/233941.747480:1674927012:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.747563:1674927087:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.747637:1674927162:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ec0 with delay 1200000\n[5016:5016:0323/233941.747726:1674927251:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.747946:1674927472:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.748048:1674927572:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.748118:1674927643:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e00 with delay 0\n[5016:5016:0323/233941.748230:1674927756: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[5016:5016:0323/233941.748313:1674927837:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e00\n[5016:5016:0323/233941.748442:1674927966:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a30 with delay 0\n[5016:5016:0323/233941.748540:1674928065:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.748614:1674928139:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c00 with delay 10000\n[5016:5016:0323/233941.748690:1674928232:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a30\n[5016:5016:0323/233941.748776:1674928301:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.748863:1674928388:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000a30 with delay 0\n[5016:5016:0323/233941.748933:1674928459:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000a30\n[5016:5016:0323/233941.749035:1674928560:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[5016:5016:0323/233941.749147:1674928672:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7688 with a delay 500000, Now = 211469424\n[5016:5016:0323/233941.749218:1674928744:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000e00 with delay 500\n[5016:5016:0323/233941.749295:1674928821:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7496 with a delay 60000000, Now = 211469424\n[5016:5016:0323/233941.749364:1674928889:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000ad0 with delay 60000\n[5016:5016:0323/233941.749445:1674928970:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000e00\n[5016:5016:0323/233941.749520:1674929046:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.749608:1674929133:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.749683:1674929226:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[5016:5016:0323/233941.749994:1674929519: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[5016:5016:0323/233941.750240:1674929766:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000c00\n[5016:5016:0323/233941.750913:1674930437:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400000c30\n[5016:5016:0323/233941.750991:1674930514:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7b0400000ad0\n[5016:5016:0323/233941.751102:1674930628: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[5016:5016:0323/233941.751177:1674930702:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[5016:5016:0323/233941.751343:1674930868: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[5016:5016:0323/233941.751422:1674930948:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7688 with a delay 500000, Now = 271469424\n[5016:5016:0323/233941.751503:1674931028:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400000c30 with delay 500\n[5016:5016:0323/233941.751575:1674931100:INFO:recurring-task.cc(55)] [Retry] Scheduling 7496 with a delay 60000000, Now = 271469424\n[5016:5016:0323/233941.751645:1674931169:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400000c00 with delay 60000\n[5016:5016:0323/233941.751736:1674931262:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7b0400000c30\n[5016:5016:0323/233941.751809:1674931334:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.751899:1674931424:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.751979:1674931507:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[5016:5016:0323/233941.752468:1674931999: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 (10 ms)\n[26/28] InvalidationClientImplTest.NetworkTimeouts (10 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[5016:5016:0323/233941.754101:1674933627:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e10 with delay 0\n[5016:5016:0323/233941.754214:1674933741:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.754592:1674934120:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0\n[5016:5016:0323/233941.754669:1674934193:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e10\n[5016:5016:0323/233941.754748:1674934272:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0\n[5016:5016:0323/233941.754892:1674934417:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.755002:1674934527:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[5016:5016:0323/233941.755078:1674934602:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[5016:5016:0323/233941.755146:1674934673:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.755219:1674934744:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0\n[5016:5016:0323/233941.755288:1674934812:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0\n[5016:5016:0323/233941.755354:1674934879:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.755431:1674934956:INFO:recurring-task.cc(55)] [Startup] Scheduling 8456 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.755507:1674935032:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[5016:5016:0323/233941.755579:1674935104:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[5016:5016:0323/233941.755733:1674935259:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3029684314615764721\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.755816:1674935340:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8072 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.755898:1674935431:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 500\n[5016:5016:0323/233941.755999:1674935532:INFO:recurring-task.cc(55)] [Retry] Scheduling 8456 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.756096:1674935627:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000db0 with delay 60000\n[5016:5016:0323/233941.756205:1674935741:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0\n[5016:5016:0323/233941.756308:1674935842:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.756429:1674935962:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.756934:1674936477: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: \"3029684314615764721\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.757223:1674936767:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000af0 with delay 0\n[5016:5016:0323/233941.757351:1674936893:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0\n[5016:5016:0323/233941.757799:1674937340:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3029684314615764721\" 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[5016:5016:0323/233941.757963:1674937503:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3029684314615764721\"\n[5016:5016:0323/233941.758090:1674937631:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.758224:1674937762:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.758343:1674937879:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e00 with delay 1200000\n[5016:5016:0323/233941.758460:1674938006:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.758825:1674938369:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.758961:1674938502:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.759092:1674938634:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ad0 with delay 0\n[5016:5016:0323/233941.759273:1674938810: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[5016:5016:0323/233941.759406:1674938943:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ad0\n[5016:5016:0323/233941.759611:1674939153:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a30 with delay 0\n[5016:5016:0323/233941.759765:1674939306:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.759887:1674939427:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e10 with delay 10000\n[5016:5016:0323/233941.760014:1674939554:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a30\n[5016:5016:0323/233941.760123:1674939661:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.760254:1674939794:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.760388:1674939925:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000a30 with delay 0\n[5016:5016:0323/233941.760519:1674940056:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000a30\n[5016:5016:0323/233941.760825:1674940365: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[5016:5016:0323/233941.761129:1674940668:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e10\n[5016:5016:0323/233941.762197:1674941740: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 (9 ms)\n[27/28] InvalidationClientImplTest.NoRegistrationSummary (9 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[5016:5016:0323/233941.763732:1674943273:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c70 with delay 0\n[5016:5016:0323/233941.763915:1674943456:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[5016:5016:0323/233941.764475:1674944036:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 0\n[5016:5016:0323/233941.764595:1674944121:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c70\n[5016:5016:0323/233941.764666:1674944188:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b50\n[5016:5016:0323/233941.764830:1674944357:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[5016:5016:0323/233941.764947:1674944472:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[5016:5016:0323/233941.765029:1674944554:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[5016:5016:0323/233941.765104:1674944630:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[5016:5016:0323/233941.765178:1674944704:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 0\n[5016:5016:0323/233941.765252:1674944776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b50\n[5016:5016:0323/233941.765320:1674944844:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[5016:5016:0323/233941.765394:1674944920:INFO:recurring-task.cc(55)] [Startup] Scheduling 7784 with a delay 0, Now = 210919424\n[5016:5016:0323/233941.765468:1674945000:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 0\n[5016:5016:0323/233941.765545:1674945069:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ad0\n[5016:5016:0323/233941.765686:1674945223:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2428869602839394380\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[5016:5016:0323/233941.765779:1674945304:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[5016:5016:0323/233941.765851:1674945377:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 500\n[5016:5016:0323/233941.765922:1674945446:INFO:recurring-task.cc(55)] [Retry] Scheduling 7784 with a delay 60000000, Now = 210919424\n[5016:5016:0323/233941.765995:1674945521:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000aa0 with delay 60000\n[5016:5016:0323/233941.766073:1674945598:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b50\n[5016:5016:0323/233941.766142:1674945667:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.766226:1674945751:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[5016:5016:0323/233941.766524:1674946050: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: \"2428869602839394380\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[5016:5016:0323/233941.766722:1674946248:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b50 with delay 0\n[5016:5016:0323/233941.766798:1674946324:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b50\n[5016:5016:0323/233941.767061:1674946587:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2428869602839394380\" 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[5016:5016:0323/233941.767167:1674946693:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2428869602839394380\"\n[5016:5016:0323/233941.767247:1674946773:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[5016:5016:0323/233941.767323:1674946848:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424\n[5016:5016:0323/233941.767398:1674946926:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a30 with delay 1200000\n[5016:5016:0323/233941.767480:1674947011:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[5016:5016:0323/233941.767730:1674947256:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.767813:1674947339:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424\n[5016:5016:0323/233941.767889:1674947415:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ad0 with delay 0\n[5016:5016:0323/233941.768007:1674947532: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[5016:5016:0323/233941.768088:1674947613:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ad0\n[5016:5016:0323/233941.768215:1674947742:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000af0 with delay 0\n[5016:5016:0323/233941.768298:1674947825:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424\n[5016:5016:0323/233941.768370:1674947897:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c70 with delay 10000\n[5016:5016:0323/233941.768442:1674947967:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0\n[5016:5016:0323/233941.768542:1674948073:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[5016:5016:0323/233941.768778:1674948304:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000c70\n[5016:5016:0323/233941.769417:1674948940:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400000aa0\n[5016:5016:0323/233941.786160:1674965690:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7b0400000a30\n[5016:5016:0323/233941.786292:1674965819:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.786408:1674965933:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[5016:5016:0323/233941.786497:1674966023:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[5016:5016:0323/233941.786899:1674966427: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[5016:5016:0323/233941.787004:1674966529:INFO:recurring-task.cc(55)] [Send-info] Scheduling 8456 with a delay 500000, Now = 1411419424\n[5016:5016:0323/233941.787088:1674966614:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400000aa0 with delay 500\n[5016:5016:0323/233941.787165:1674966691:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424\n[5016:5016:0323/233941.787238:1674966763:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400000c70 with delay 1200000\n[5016:5016:0323/233941.787317:1674966841:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7b0400000aa0\n[5016:5016:0323/233941.787387:1674966913:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.787509:1674967034:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[5016:5016:0323/233941.787582:1674967108:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[5016:5016:0323/233941.788102:1674967627:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: \"2\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } performance_counter: { name: \"SentMessageType.INITIALIZE\" value: 1 } performance_counter: { name: \"SentMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOKEN_CONTROL\" value: 1 } performance_counter: { name: \"ReceivedMessageType.TOTAL\" value: 1 } performance_counter: { name: \"ListenerEventType.REISSUE_REGISTRATIONS\" value: 1 } performance_counter: { name: \"ClientErrorType.PERSISTENT_READ_FAILURE\" value: 1 } server_registration_summary_requested: false } }\n[ OK ] InvalidationClientImplTest.Heartbeats (27 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (27 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "f7ee28e295189c5f489297a733e6d1d60d9e6c0a", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "43c73e9235ff3311", "server_versions": [ "4216-cf4a3cd" ], "started_ts": "2019-03-24T06:39:36.951668", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux TSan Tests", "buildnumber:35963", "cpu:x86-64", "data:87420490074df7bc8dc9174fc63c4d13aa462c60", "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:swarm323-c4", "spec_name:chromium.ci:Linux TSan Tests", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:d172b3da50f79bdc0892909417b8871a46e09913", "user:None" ], "task_id": "43c9cb706e01c410" } ] }