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

{ "shards": [ { "bot_dimensions": [ { "key": "caches", "value": [ "swarming_module_cache_vpython", "xcode_ios_10b61", "xcode_ios_10l232m", "xcode_ios_10o45e" ] }, { "key": "cores", "value": [ "8" ] }, { "key": "cpu", "value": [ "x86", "x86-64", "x86-64-E5-2697_v2" ] }, { "key": "gce", "value": [ "0" ] }, { "key": "gpu", "value": [ "none" ] }, { "key": "id", "value": [ "vm291-m9" ] }, { "key": "mac_model", "value": [ "VMware7,1" ] }, { "key": "machine_type", "value": [ "n1-highcpu-8" ] }, { "key": "os", "value": [ "Mac", "Mac-10.13", "Mac-10.13.6" ] }, { "key": "pool", "value": [ "Chrome" ] }, { "key": "python", "value": [ "2.7.10" ] }, { "key": "server_version", "value": [ "4267-53b17d5" ] }, { "key": "ssd", "value": [ "1" ] }, { "key": "zone", "value": [ "us", "us-golo", "us-golo-9" ] } ], "bot_id": "vm291-m9", "bot_version": "bd68e04e43fc4d1b7b5b65890a29c5d5bae55ab1423851733f92abd7e13dda14", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/mac-amd64", "version": "1vQ99wQk82cRyVYu18rqMpXtb7XZ3WHvL3HFXTcLHN4C" }, "packages": [ { "package_name": "infra/python/cpython/mac-amd64", "path": ".swarming_module", "version": "6dd10e31dc5d4cbb3c8f42a6fbd9485aeeb9ef0c" }, { "package_name": "infra/tools/luci/logdog/butler/mac-amd64", "path": ".swarming_module", "version": "3138aa2054ab30eac6f7e1e589e590571ae44692" }, { "package_name": "infra/tools/luci/vpython-native/mac-amd64", "path": ".swarming_module", "version": "QDLPZ3UAgZNoR5d69kckoahXHUl1oKiq5UVzhbr3X4EC" }, { "package_name": "infra/tools/luci/vpython/mac-amd64", "path": ".swarming_module", "version": "up_SZsefNVjCYV99Mh2FddLgkRCR_FxXo_Qn2bhROIsC" } ] }, "completed_ts": "2019-04-19T18:46:52.162865", "cost_saved_usd": 0.0028796095161420774, "created_ts": "2019-04-21T06:40:03.370296", "deduped_from": "444fbd8c19383a11", "duration": 1.9512810707092285, "modified_ts": "2019-04-21T06:40:03.381605", "name": "cacheinvalidation_unittests/Mac-10.13/a621f1f4f5/Mac ASan 64 Tests (1)/52113", "output": "Additional test environment:\n ASAN_OPTIONS=symbolize=0 handle_abort=1\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n DYLD_LIBRARY_PATH=/b/s/w/ir/out/Release\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioNXqrHk/output.json\n\nIMPORTANT DEBUGGING NOTE: batches of tests are run inside their\nown process. For debugging a test inside a debugger, use the\n--gtest_filter=<your_test_name> flag along with\n--single-process-tests.\nUsing sharding settings from environment. This is shard 0/1\nUsing 8 parallel jobs.\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[19086:775:0419/114648.289768:21494899317462:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007910 with delay 0\n[19086:775:0419/114648.290844:21494899911330:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007910\n[19086:775:0419/114648.291087:21494900152944: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[19086:775:0419/114648.291222:21494900290849:INFO:recurring-task.cc(55)] [Startup] Scheduling 24744 with a delay 500000, Now = 210919424\n[19086:775:0419/114648.291300:21494900366343:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007ab0 with delay 500\n[19086:775:0419/114648.291368:21494900426059:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007ab0\n[19086:775:0419/114648.291886:21494900945845:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } initialize_message: { client_type: 2 nonce: \"unit-test-nonce\" application_client_id: { client_type: 2 client_name: \"unit-test-client-id\" } digest_serialization_type: BYTE_BASED } }\n[ OK ] ProtocolHandlerTest.SendInitializeOnly (5 ms)\n[1/28] ProtocolHandlerTest.SendInitializeOnly (5 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[19086:775:0419/114648.293881:21494902948223: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[19086:775:0419/114648.294665:21494903729843:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000086f0 with delay 0\n[19086:775:0419/114648.294953:21494904019741:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008710 with delay 0\n[19086:775:0419/114648.295085:21494904150965:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008730 with delay 0\n[19086:775:0419/114648.295252:21494904311167:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008750 with delay 0\n[19086:775:0419/114648.295333:21494904391317:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008770 with delay 0\n[19086:775:0419/114648.295432:21494904490491:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008790 with delay 0\n[19086:775:0419/114648.296189:21494905248358:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000086f0\n[19086:775:0419/114648.296399:21494905458247: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[19086:775:0419/114648.296498:21494905557041:INFO:recurring-task.cc(55)] [Send-info] Scheduling 69032 with a delay 500000, Now = 210919424\n[19086:775:0419/114648.296564:21494905622448:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008930 with delay 500\n[19086:775:0419/114648.296620:21494905678677:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008710\n[19086:775:0419/114648.296694:21494905752000:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008730\n[19086:775:0419/114648.296744:21494905802197:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008750\n[19086:775:0419/114648.296809:21494905866563:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008770\n[19086:775:0419/114648.296874:21494905931862:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008790\n[19086:775:0419/114648.296951:21494906009419:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[19086:775:0419/114648.297033:21494906091741:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008930\n[19086:775:0419/114648.297338:21494906396540:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[19086:775:0419/114648.297882:21494906941010: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[19086:775:0419/114648.299853:21494908912547: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[19086:775:0419/114648.300580:21494909640442: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[19086:775:0419/114648.300711:21494909769864: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[19086:775:0419/114648.300847:21494909905905: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[19086:775:0419/114648.300985:21494910043327:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[5/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[19086:775:0419/114648.301573:21494910632364: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[19086:775:0419/114648.301717:21494910775770:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (0 ms)\n[6/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[19086:775:0419/114648.302223:21494911282492: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[19086:775:0419/114648.302898:21494911959215: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[19086:775:0419/114648.302998:21494912058173:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a470 with delay 0\n[19086:775:0419/114648.303067:21494912126262:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a470\n[19086:775:0419/114648.303166:21494912225133: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[19086:775:0419/114648.303249:21494912308882:INFO:recurring-task.cc(55)] [Send-info] Scheduling 100136 with a delay 500000, Now = 210919424\n[19086:775:0419/114648.303311:21494912370820:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a490 with delay 500\n[19086:775:0419/114648.303365:21494912423738:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a490\n[19086:775:0419/114648.303442:21494912501190:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (9 ms)\n[8/28] ProtocolHandlerTest.ConfigMessage (9 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[19086:775:0419/114648.312203:21494921263538: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[19086:775:0419/114648.312875:21494921942648: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[19087:775:0419/114648.309784:21494919578307:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006910 with delay 0\n[19087:775:0419/114648.310689:21494919757714:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006910\n[19087:775:0419/114648.310964:21494920031907: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[19087:775:0419/114648.311113:21494920173138:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24744 with a delay 500000, Now = 210919424\n[19087:775:0419/114648.311175:21494920235139:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006930 with delay 500\n[19087:775:0419/114648.311244:21494920303520:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006930\n[19087:775:0419/114648.311407:21494920482295:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[19087:775:0419/114648.311487:21494920546129:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (3 ms)\n[11/28] ProtocolHandlerTest.TokenMissing (3 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[19087:775:0419/114648.312345:21494921405629:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006eb0 with delay 0\n[19087:775:0419/114648.312408:21494921466909:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006eb0\n[19087:775:0419/114648.312499:21494921558760:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 29736 with a delay 500000, Now = 210919424\n[19087:775:0419/114648.312570:21494921636681:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006ed0 with delay 500\n[19087:775:0419/114648.312652:21494921711757:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006ed0\n[19087:775:0419/114648.312865:21494921924688:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[19087:775:0419/114648.313028:21494922087230: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[19087:775:0419/114648.313167:21494922226030: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[19087:775:0419/114648.313419:21494922478954: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[19087:775:0419/114648.313649:21494922709250:ERROR:protocol-handler.cc(323)] Tried to send invalid message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true is_trickle_restart: true } } }\n[ OK ] ProtocolHandlerTest.InvalidOutboundMessage (1 ms)\n[12/28] ProtocolHandlerTest.InvalidOutboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[19087:775:0419/114648.314289:21494923357391:INFO:protocol-handler.cc(139)] Incoming message: { }\n[19087:775:0419/114648.314386:21494923446218:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[19087:775:0419/114648.314484:21494923550702:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms)\n[13/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[19087:775:0419/114648.314912:21494923973908:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -361083960 with a delay 10000, Now = 0\n[19087:775:0419/114648.314989:21494924048982:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000007590 with delay 10\n[19087:775:0419/114648.315073:21494924133082:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000007590\n[19087:775:0419/114648.315129:21494924189281:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[19087:775:0419/114648.315194:21494924253260:INFO:recurring-task.cc(55)] [Retry] Scheduling -361083960 with a delay 60000, Now = 10000\n[19087:775:0419/114648.315267:21494924326698:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x6020000075b0 with delay 60\n[19087:775:0419/114648.315335:21494924394763:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x6020000075b0\n[19087:775:0419/114648.315390:21494924449479:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[19087:775:0419/114648.315436:21494924495501:INFO:recurring-task.cc(55)] [Retry] Scheduling -361083960 with a delay 60000, Now = 70000\n[19087:775:0419/114648.315482:21494924541708:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000075d0 with delay 60\n[19087:775:0419/114648.315529:21494924587865:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000075d0\n[19087:775:0419/114648.315608:21494924667624:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[19087:775:0419/114648.315654:21494924713081:INFO:recurring-task.cc(55)] [Retry] Scheduling -361083960 with a delay 60000, Now = 130000\n[19087:775:0419/114648.315710:21494924769180:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000075f0 with delay 60\n[19087:775:0419/114648.315756:21494924815364:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000075f0\n[19087:775:0419/114648.315799:21494924858481:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[19087:775:0419/114648.315843:21494924901882:INFO:recurring-task.cc(55)] [Retry] Scheduling -361083960 with a delay 60000, Now = 190000\n[19087:775:0419/114648.315888:21494924946932:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x602000007610 with delay 60\n[19087:775:0419/114648.315933:21494924992118:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x602000007610\n[19087:775:0419/114648.315976:21494925034959:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[19087:775:0419/114648.316030:21494925089478:INFO:recurring-task.cc(55)] [Retry] Scheduling -361083960 with a delay 60000, Now = 250000\n[19087:775:0419/114648.316076:21494925135320:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000007630 with delay 60\n[19087:775:0419/114648.316122:21494925180991:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000007630\n[19087:775:0419/114648.316175:21494925234347:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[19087:775:0419/114648.316219:21494925277949:INFO:recurring-task.cc(55)] [Retry] Scheduling -361083960 with a delay 60000, Now = 310000\n[19087:775:0419/114648.316264:21494925322821:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000007650 with delay 60\n[19087:775:0419/114648.316309:21494925368223:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000007650\n[19087:775:0419/114648.316377:21494925437157:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[19087:775:0419/114648.316424:21494925482931:INFO:recurring-task.cc(55)] [Retry] Scheduling -361083960 with a delay 60000, Now = 370000\n[19087:775:0419/114648.316469:21494925528185:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000007670 with delay 60\n[19087:775:0419/114648.316515:21494925574305:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000007670\n[19087:775:0419/114648.316594:21494925653331:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (2 ms)\n[14/28] RecurringTaskTest.PeriodicTask (2 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[19087:775:0419/114648.317024:21494926084185:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -361084312 with a delay 10000, Now = 0\n[19087:775:0419/114648.317085:21494926144604:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x6020000076f0 with delay 10\n[19087:775:0419/114648.317175:21494926235429:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x6020000076f0\n[19087:775:0419/114648.317244:21494926310322:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[19087:775:0419/114648.317317:21494926376150:INFO:recurring-task.cc(55)] [Retry] Scheduling -361084312 with a delay 50000, Now = 10000\n[19087:775:0419/114648.317389:21494926449680:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000007710 with delay 50\n[19087:775:0419/114648.317462:21494926521721:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000007710\n[19087:775:0419/114648.317523:21494926582677:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[19087:775:0419/114648.317589:21494926655047:INFO:recurring-task.cc(55)] [Retry] Scheduling -361084312 with a delay 149000, Now = 60000\n[19087:775:0419/114648.317658:21494926718191:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000007730 with delay 149\n[19087:775:0419/114648.317728:21494926788064:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000007730\n[19087:775:0419/114648.317784:21494926843283:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[19087:775:0419/114648.317849:21494926908651:INFO:recurring-task.cc(55)] [Retry] Scheduling -361084312 with a delay 248000, Now = 210000\n[19087:775:0419/114648.317904:21494926963623:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000007750 with delay 248\n[19087:775:0419/114648.317962:21494927021525:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000007750\n[19087:775:0419/114648.318022:21494927089805:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[19087:775:0419/114648.318083:21494927142764:INFO:recurring-task.cc(55)] [Retry] Scheduling -361084312 with a delay 446000, Now = 460000\n[19087:775:0419/114648.318147:21494927206979:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000007770 with delay 446\n[19087:775:0419/114648.318219:21494927278369:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000007770\n[19087:775:0419/114648.318301:21494927367757:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[19087:775:0419/114648.318374:21494927433978:INFO:recurring-task.cc(55)] [Retry] Scheduling -361084312 with a delay 842000, Now = 910000\n[19087:775:0419/114648.318441:21494927500397:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000007790 with delay 842\n[19087:775:0419/114648.318500:21494927559605:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000007790\n[19087:775:0419/114648.318554:21494927613085:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[19087:775:0419/114648.318598:21494927657247:INFO:recurring-task.cc(55)] [Retry] Scheduling -361084312 with a delay 1040000, Now = 1760000\n[19087:775:0419/114648.318650:21494927709741:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x6020000077b0 with delay 1040\n[19087:775:0419/114648.318704:21494927763131:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x6020000077b0\n[19087:775:0419/114648.318760:21494927819707:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[19087:775:0419/114648.318806:21494927865404:INFO:recurring-task.cc(55)] [Retry] Scheduling -361084312 with a delay 1040000, Now = 2800000\n[19087:775:0419/114648.318852:21494927910951:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x6020000077d0 with delay 1040\n[19087:775:0419/114648.318902:21494927961887:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x6020000077d0\n[19087:775:0419/114648.318946:21494928005091:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[15/28] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[19087:775:0419/114648.319291:21494928351348:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -361084280 with a delay 10000, Now = 0\n[19087:775:0419/114648.319367:21494928426537:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000007850 with delay 10\n[19087:775:0419/114648.319417:21494928476028:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000007850\n[19087:775:0419/114648.319488:21494928547564:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[19087:775:0419/114648.319563:21494928622920:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -361084280 with a delay 10000, Now = 10000\n[19087:775:0419/114648.319631:21494928690417:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000007870 with delay 10\n[19087:775:0419/114648.319698:21494928765110:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000007870\n[19087:775:0419/114648.319759:21494928818537: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[19087:775:0419/114648.320266:21494929326057:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x6020000078f0 with delay 920\n[19087:775:0419/114648.320339:21494929398388:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x6020000078f0\n[19087:775:0419/114648.320479:21494929538645:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000007910 with delay 45000\n[19087:775:0419/114648.320736:21494929804442:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000007910\n[ OK ] ThrottleTest.ThrottlingScripted (0 ms)\n[17/28] ThrottleTest.ThrottlingScripted (0 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[19087:775:0419/114648.320946:21494930005861:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000007990 with delay 990\n[19087:775:0419/114648.321032:21494930091585:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000007990\n[19087:775:0419/114648.321103:21494930162143:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x6020000079b0 with delay 1000\n[19087:775:0419/114648.321158:21494930217521:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x6020000079b0\n[19087:775:0419/114648.321207:21494930266198:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x6020000079d0 with delay 1000\n[19087:775:0419/114648.321260:21494930319271:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x6020000079d0\n[19087:775:0419/114648.321308:21494930367029:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x6020000079f0 with delay 1000\n[19087:775:0419/114648.321361:21494930420687:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x6020000079f0\n[19087:775:0419/114648.321419:21494930509102:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000007a10 with delay 1000\n[19087:775:0419/114648.321507:21494930566963:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000007a10\n[19087:775:0419/114648.321556:21494930615840:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000007a30 with delay 1000\n[19087:775:0419/114648.321609:21494930668649:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000007a30\n[19087:775:0419/114648.321686:21494930746679:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000007a50 with delay 54000\n[19087:775:0419/114648.322152:21494931211302:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000007a50\n[19087:775:0419/114648.322211:21494931270417:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000007a70 with delay 1000\n[19087:775:0419/114648.322266:21494931325310:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000007a70\n[19087:775:0419/114648.322324:21494931384030:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000007a90 with delay 1000\n[19087:775:0419/114648.322378:21494931437192:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000007a90\n[19087:775:0419/114648.322426:21494931485268:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000007ab0 with delay 1000\n[19087:775:0419/114648.322479:21494931538124:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000007ab0\n[19087:775:0419/114648.322527:21494931586078:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000007ad0 with delay 1000\n[19087:775:0419/114648.322579:21494931638664:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000007ad0\n[19087:775:0419/114648.322627:21494931686311:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000007af0 with delay 1000\n[19087:775:0419/114648.322694:21494931753757:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000007af0\n[19087:775:0419/114648.322754:21494931813642:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000007b10 with delay 1000\n[19087:775:0419/114648.322810:21494931869121:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000007b10\n[19087:775:0419/114648.322856:21494931915618:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000007b30 with delay 54000\n[19087:775:0419/114648.323317:21494932376324:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000007b30\n[19087:775:0419/114648.323364:21494932423760:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000007b50 with delay 1000\n[19087:775:0419/114648.323417:21494932476620:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000007b50\n[19087:775:0419/114648.323464:21494932523780:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000007b70 with delay 1000\n[19087:775:0419/114648.323517:21494932576688:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000007b70\n[19087:775:0419/114648.323576:21494932635287:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000007b90 with delay 1000\n[19087:775:0419/114648.323629:21494932688338:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000007b90\n[19087:775:0419/114648.323686:21494932746040:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000007bb0 with delay 1000\n[19087:775:0419/114648.323749:21494932808158:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000007bb0\n[19087:775:0419/114648.323797:21494932856580:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000007bd0 with delay 1000\n[19087:775:0419/114648.323850:21494932909130:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000007bd0\n[19087:775:0419/114648.323897:21494932956570:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000007bf0 with delay 1000\n[19087:775:0419/114648.323950:21494933009663:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000007bf0\n[19087:775:0419/114648.324006:21494933065659:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000007c10 with delay 54000\n[19087:775:0419/114648.324467:21494933526484:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000007c10\n[19087:775:0419/114648.324515:21494933574123:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000007c30 with delay 1000\n[19087:775:0419/114648.324579:21494933639287:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000007c30\n[19087:775:0419/114648.324629:21494933688805:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000007c50 with delay 1000\n[19087:775:0419/114648.324682:21494933741760:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000007c50\n[19087:775:0419/114648.324738:21494933798070:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000007c70 with delay 1000\n[19087:775:0419/114648.324792:21494933851007:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000007c70\n[19087:775:0419/114648.324850:21494933910045:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000007c90 with delay 1000\n[19087:775:0419/114648.324905:21494933964137:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000007c90\n[19087:775:0419/114648.324952:21494934011498:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000007cb0 with delay 1000\n[19087:775:0419/114648.325011:21494934071187:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000007cb0\n[19087:775:0419/114648.325061:21494934120530:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x602000007cd0 with delay 1000\n[19087:775:0419/114648.325127:21494934187251:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x602000007cd0\n[19087:775:0419/114648.325185:21494934245344:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x602000007cf0 with delay 54000\n[19087:775:0419/114648.325648:21494934707602:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x602000007cf0\n[19087:775:0419/114648.325706:21494934765888:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x602000007d10 with delay 1000\n[19087:775:0419/114648.325759:21494934818831:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x602000007d10\n[19087:775:0419/114648.325807:21494934866791:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000007d30 with delay 1000\n[19087:775:0419/114648.325860:21494934919223:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000007d30\n[19087:775:0419/114648.325907:21494934966988:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000007d50 with delay 1000\n[19087:775:0419/114648.325960:21494935019704:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000007d50\n[19087:775:0419/114648.326007:21494935066857:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000007d70 with delay 1000\n[19087:775:0419/114648.326060:21494935119528:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000007d70\n[19087:775:0419/114648.326118:21494935177698:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000007d90 with delay 1000\n[19087:775:0419/114648.326171:21494935230819:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000007d90\n[19087:775:0419/114648.326219:21494935278324:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000007db0 with delay 1000\n[19087:775:0419/114648.326271:21494935331122:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000007db0\n[19087:775:0419/114648.326317:21494935376860:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x602000007dd0 with delay 54000\n[19087:775:0419/114648.326782:21494935842081:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x602000007dd0\n[ OK ] ThrottleTest.ThrottlingStorm (6 ms)\n[18/28] ThrottleTest.ThrottlingStorm (6 ms)\n[ RUN ] InvalidationClientImplTest.Start\n[19085:775:0419/114648.312389:21494921908660:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006c50 with delay 0\n[19085:775:0419/114648.313138:21494922198879:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.313699:21494922759738:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007170 with delay 0\n[19085:775:0419/114648.313769:21494922828667:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006c50\n[19085:775:0419/114648.313868:21494922927402:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007170\n[19085:775:0419/114648.313992:21494923052321:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.314152:21494923218849:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007230 with delay 0\n[19085:775:0419/114648.314240:21494923299428:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007230\n[19085:775:0419/114648.314287:21494923346152:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.314357:21494923416580:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007270 with delay 0\n[19085:775:0419/114648.314407:21494923465631:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007270\n[19085:775:0419/114648.314536:21494923596468:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.314622:21494923681318:INFO:recurring-task.cc(55)] [Startup] Scheduling 25000 with a delay 0, Now = 210919424\n[19085:775:0419/114648.314681:21494923746834:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0\n[19085:775:0419/114648.314738:21494923796854:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290\n[19085:775:0419/114648.314884:21494923944214:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6688782867150917564\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.314976:21494924035627:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 25256 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.315042:21494924109288:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000072b0 with delay 500\n[19085:775:0419/114648.315105:21494924164350:INFO:recurring-task.cc(55)] [Retry] Scheduling 25000 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.315174:21494924240802:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000072d0 with delay 60000\n[19085:775:0419/114648.315245:21494924304167:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000072b0\n[19085:775:0419/114648.315340:21494924399517:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.315501:21494924560658:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.315720:21494924780789: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: \"6688782867150917564\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.316090:21494925149942:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007370 with delay 0\n[19085:775:0419/114648.316178:21494925237220:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007370\n[19085:775:0419/114648.316389:21494925459814:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6688782867150917564\" 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[19085:775:0419/114648.316563:21494925622688:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6688782867150917564\"\n[19085:775:0419/114648.316643:21494925702755:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.316720:21494925779412:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 21720 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.316792:21494925858913:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007390 with delay 1200000\n[19085:775:0419/114648.316887:21494925946892:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.317176:21494926235573:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.317255:21494926322317:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 21384 with a delay 0, Now = 211419424\n[19085:775:0419/114648.317328:21494926387491:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000075b0 with delay 0\n[19085:775:0419/114648.317432:21494926498539: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[19085:775:0419/114648.317525:21494926583994:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000075b0\n[19085:775:0419/114648.317673:21494926732533:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007670 with delay 0\n[19085:775:0419/114648.317762:21494926820970:INFO:recurring-task.cc(55)] [Retry] Scheduling 21384 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.317831:21494926890581:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076b0 with delay 10000\n[19085:775:0419/114648.317888:21494926947012:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007670\n[19085:775:0419/114648.317943:21494927001880:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[ OK ] InvalidationClientImplTest.Start (8 ms)\n[19/28] InvalidationClientImplTest.Start (8 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[19085:775:0419/114648.318849:21494927909733:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007f10 with delay 0\n[19085:775:0419/114648.318917:21494927976581: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[19085:775:0419/114648.319510:21494928570573:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0\n[19085:775:0419/114648.319578:21494928637082:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.320055:21494929115009:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008e10 with delay 0\n[19085:775:0419/114648.320122:21494929181551:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0\n[19085:775:0419/114648.320178:21494929237480:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008e10\n[19085:775:0419/114648.320260:21494929319519:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.320357:21494929417410:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008ed0 with delay 0\n[19085:775:0419/114648.320420:21494929479007:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008ed0\n[19085:775:0419/114648.320478:21494929537410:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.320549:21494929608667:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f10 with delay 0\n[19085:775:0419/114648.320611:21494929670170:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008f10\n[19085:775:0419/114648.320665:21494929724252:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.320745:21494929805607:INFO:recurring-task.cc(55)] [Startup] Scheduling 81704 with a delay 0, Now = 210919424\n[19085:775:0419/114648.320809:21494929897053:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f30 with delay 0\n[19085:775:0419/114648.320890:21494929949648:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008f30\n[19085:775:0419/114648.320980:21494930047121:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4739143217036975492\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.321064:21494930123690:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 81960 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.321138:21494930197952:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f50 with delay 500\n[19085:775:0419/114648.321200:21494930260215:INFO:recurring-task.cc(55)] [Retry] Scheduling 81704 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.321271:21494930330970:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f70 with delay 60000\n[19085:775:0419/114648.321343:21494930402718:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008f50\n[19085:775:0419/114648.321400:21494930459242:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.321479:21494930538352:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.321657:21494930717131: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: \"4739143217036975492\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.321821:21494930881051:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009010 with delay 0\n[19085:775:0419/114648.321886:21494930945693:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009010\n[19085:775:0419/114648.322026:21494931085991:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4739143217036975492\" 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[19085:775:0419/114648.322133:21494931192802:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4739143217036975492\"\n[19085:775:0419/114648.322210:21494931269775:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.322283:21494931342959:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 89656 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.322340:21494931400082:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009030 with delay 1200000\n[19085:775:0419/114648.322398:21494931457701:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.322615:21494931674852:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.322688:21494931747988:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 66120 with a delay 0, Now = 211419424\n[19085:775:0419/114648.322738:21494931798015:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009250 with delay 0\n[19085:775:0419/114648.322838:21494931897851: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[19085:775:0419/114648.322908:21494931967209:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009250\n[19085:775:0419/114648.323013:21494932072760:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009310 with delay 0\n[19085:775:0419/114648.323083:21494932142482:INFO:recurring-task.cc(55)] [Retry] Scheduling 66120 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.323146:21494932205251:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009350 with delay 10000\n[19085:775:0419/114648.323195:21494932254199:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009310\n[19085:775:0419/114648.323246:21494932306208:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.323379:21494932439691:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009370 with delay 0\n[19085:775:0419/114648.323444:21494932503613:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000009370\n[19085:775:0419/114648.323521:21494932580961:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[19085:775:0419/114648.323591:21494932650155:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[19085:775:0419/114648.323653:21494932712539:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[19085:775:0419/114648.323790:21494932850610:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 81960 with a delay 500000, Now = 211469424\n[19085:775:0419/114648.323865:21494932924672:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009390 with delay 500\n[19085:775:0419/114648.323927:21494932995408:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 81832 with a delay 60000000, Now = 211469424\n[19085:775:0419/114648.323999:21494933058839:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000093b0 with delay 60000\n[19085:775:0419/114648.324062:21494933121952:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009390\n[19085:775:0419/114648.324126:21494933185929:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.324205:21494933264899:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.324261:21494933320287:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19085:775:0419/114648.324467:21494933527433: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[19085:775:0419/114648.324665:21494933725001:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.324835:21494933895593:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000009450 with delay 0\n[19085:775:0419/114648.324901:21494933968434:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009450\n[19085:775:0419/114648.325150:21494934211133: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[19085:775:0419/114648.325352:21494934412259: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[19085:775:0419/114648.325470:21494934530335:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[19085:775:0419/114648.325611:21494934671112:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[19085:775:0419/114648.325721:21494934781454:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[19085:775:0419/114648.325876:21494934935653:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000009350\n[ OK ] InvalidationClientImplTest.Register (7 ms)\n[21/28] InvalidationClientImplTest.Register (7 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[19085:775:0419/114648.326825:21494935886033:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a030 with delay 0\n[19085:775:0419/114648.326893:21494935952911:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.327363:21494936423430:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a710 with delay 0\n[19085:775:0419/114648.327425:21494936484769:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a030\n[19085:775:0419/114648.327487:21494936547329:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a710\n[19085:775:0419/114648.327558:21494936624390:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.327659:21494936719433:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a7d0 with delay 0\n[19085:775:0419/114648.327729:21494936788847:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a7d0\n[19085:775:0419/114648.327790:21494936849710:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.327860:21494936920530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a810 with delay 0\n[19085:775:0419/114648.327910:21494936970129:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a810\n[19085:775:0419/114648.327956:21494937015589:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.328030:21494937090310:INFO:recurring-task.cc(55)] [Startup] Scheduling 112808 with a delay 0, Now = 210919424\n[19085:775:0419/114648.328095:21494937155335:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a830 with delay 0\n[19085:775:0419/114648.328151:21494937210999:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a830\n[19085:775:0419/114648.328244:21494937304627:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1166080444193167033\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.328315:21494937375614:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 113064 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.328365:21494937437381:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a850 with delay 500\n[19085:775:0419/114648.328432:21494937491635:INFO:recurring-task.cc(55)] [Retry] Scheduling 112808 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.328493:21494937553430:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a870 with delay 60000\n[19085:775:0419/114648.328554:21494937613991:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a850\n[19085:775:0419/114648.328609:21494937669297:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.328672:21494937732473:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.328859:21494937919678: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: \"1166080444193167033\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.329017:21494938077970:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a910 with delay 0\n[19085:775:0419/114648.329088:21494938148518:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a910\n[19085:775:0419/114648.329235:21494938295489:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1166080444193167033\" 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[19085:775:0419/114648.329351:21494938411387:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1166080444193167033\"\n[19085:775:0419/114648.329409:21494938470300:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.329475:21494938535659:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 94760 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.329532:21494938591571:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a930 with delay 1200000\n[19085:775:0419/114648.329583:21494938642440:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.329799:21494938860435:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.329872:21494938932042:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 72456 with a delay 0, Now = 211419424\n[19085:775:0419/114648.329935:21494939004151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ab50 with delay 0\n[19085:775:0419/114648.330022:21494939082581: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[19085:775:0419/114648.330098:21494939157512:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ab50\n[19085:775:0419/114648.330190:21494939250140:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ac10 with delay 0\n[19085:775:0419/114648.330279:21494939339671:INFO:recurring-task.cc(55)] [Retry] Scheduling 72456 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.330337:21494939397841:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ac50 with delay 10000\n[19085:775:0419/114648.330386:21494939446229:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ac10\n[19085:775:0419/114648.330431:21494939490898:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.330511:21494939579079:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.330614:21494939674077:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000ac70 with delay 0\n[19085:775:0419/114648.330665:21494939733433:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000ac70\n[19085:775:0419/114648.330941:21494940002651: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[19085:775:0419/114648.331058:21494940119051: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[19085:775:0419/114648.331161:21494940221658: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[19085:775:0419/114648.331311:21494940371598: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[19085:775:0419/114648.331423:21494940483254: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[19085:775:0419/114648.331550:21494940610453:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b050 with delay 0\n[19085:775:0419/114648.331612:21494940672250:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b070 with delay 0\n[19085:775:0419/114648.331684:21494940743962:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b090 with delay 0\n[19085:775:0419/114648.331731:21494940791257:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x60200000b050\n[19085:775:0419/114648.331819:21494940879731:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 113064 with a delay 500000, Now = 211519424\n[19085:775:0419/114648.331887:21494940946715:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x60200000b0b0 with delay 500\n[19085:775:0419/114648.331959:21494941019158:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x60200000b070\n[19085:775:0419/114648.332033:21494941092772:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x60200000b090\n[19085:775:0419/114648.332101:21494941161840:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x60200000b0b0\n[19085:775:0419/114648.332158:21494941217687:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.332241:21494941301487:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.332302:21494941378142:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19085:775:0419/114648.332521:21494941581239:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: \"2\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } }\n[ OK ] InvalidationClientImplTest.Invalidations (6 ms)\n[22/28] InvalidationClientImplTest.Invalidations (6 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[19085:775:0419/114648.333309:21494942369880:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b990 with delay 0\n[19085:775:0419/114648.333385:21494942445571:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.333626:21494942686730:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000beb0 with delay 0\n[19085:775:0419/114648.333696:21494942756331:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b990\n[19085:775:0419/114648.333750:21494942810378:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000beb0\n[19085:775:0419/114648.333829:21494942889211:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.333947:21494943007973:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bf70 with delay 0\n[19085:775:0419/114648.334013:21494943073557:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000bf70\n[19085:775:0419/114648.334061:21494943120571:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.334126:21494943186987:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bfb0 with delay 0\n[19085:775:0419/114648.334184:21494943244622:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000bfb0\n[19085:775:0419/114648.334231:21494943291599:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.334298:21494943358668:INFO:recurring-task.cc(55)] [Startup] Scheduling 142504 with a delay 0, Now = 210919424\n[19085:775:0419/114648.334348:21494943416872:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bfd0 with delay 0\n[19085:775:0419/114648.334406:21494943465551:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000bfd0\n[19085:775:0419/114648.334509:21494943591102:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2846434603690909365\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.334615:21494943675751:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 142760 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.334667:21494943727114:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000bff0 with delay 500\n[19085:775:0419/114648.334730:21494943790689:INFO:recurring-task.cc(55)] [Retry] Scheduling 142504 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.334801:21494943861092:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c010 with delay 60000\n[19085:775:0419/114648.334932:21494943995600:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000bff0\n[19085:775:0419/114648.335003:21494944065022:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.335087:21494944148551:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.335236:21494944296559: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: \"-2846434603690909365\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.335379:21494944439498:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c0b0 with delay 0\n[19085:775:0419/114648.335438:21494944498747:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c0b0\n[19085:775:0419/114648.335571:21494944631185:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2846434603690909365\" 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[19085:775:0419/114648.335644:21494944718388:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2846434603690909365\"\n[19085:775:0419/114648.335716:21494944776185:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.335779:21494944839524:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 98808 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.335841:21494944900981:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c0d0 with delay 1200000\n[19085:775:0419/114648.335891:21494944950729:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.336066:21494945133865:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.336130:21494945190918:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 78216 with a delay 0, Now = 211419424\n[19085:775:0419/114648.336185:21494945245599:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c2f0 with delay 0\n[19085:775:0419/114648.336252:21494945312520: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[19085:775:0419/114648.336314:21494945374598:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c2f0\n[19085:775:0419/114648.336411:21494945471983:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c3b0 with delay 0\n[19085:775:0419/114648.336499:21494945559771:INFO:recurring-task.cc(55)] [Retry] Scheduling 78216 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.336555:21494945615878:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c3f0 with delay 10000\n[19085:775:0419/114648.336603:21494945662761:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c3b0\n[19085:775:0419/114648.336666:21494945728219:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.336786:21494945847228:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.336877:21494945937642:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000c410 with delay 0\n[19085:775:0419/114648.336934:21494945994661:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000c410\n[19085:775:0419/114648.337103:21494946163770: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[19085:775:0419/114648.337265:21494946325882: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[19085:775:0419/114648.337335:21494946396328:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[19085:775:0419/114648.337423:21494946503050:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 142760 with a delay 500000, Now = 211469424\n[19085:775:0419/114648.337539:21494946602132:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000c430 with delay 500\n[19085:775:0419/114648.337605:21494946665332:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[19085:775:0419/114648.337848:21494946908601: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[19085:775:0419/114648.337938:21494946998752:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000c430\n[19085:775:0419/114648.337993:21494947053540:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.338136:21494947196963:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.338193:21494947252969:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19085:775:0419/114648.338499:21494947560062: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[19085:775:0419/114648.338706:21494947767072:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000c3f0\n[ OK ] InvalidationClientImplTest.ServerRequests (6 ms)\n[23/28] InvalidationClientImplTest.ServerRequests (6 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[19085:775:0419/114648.339608:21494948670080:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd10 with delay 0\n[19085:775:0419/114648.339695:21494948756104:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.339974:21494949035142:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d2d0 with delay 0\n[19085:775:0419/114648.340025:21494949085637:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cd10\n[19085:775:0419/114648.340079:21494949139667:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d2d0\n[19085:775:0419/114648.340150:21494949210109:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.340244:21494949305049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d390 with delay 0\n[19085:775:0419/114648.340312:21494949372518:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d390\n[19085:775:0419/114648.340358:21494949418411:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.340405:21494949472687:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0\n[19085:775:0419/114648.340460:21494949520447:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0\n[19085:775:0419/114648.340504:21494949564017:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.340563:21494949623680:INFO:recurring-task.cc(55)] [Startup] Scheduling 169768 with a delay 0, Now = 210919424\n[19085:775:0419/114648.340610:21494949671012:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3f0 with delay 0\n[19085:775:0419/114648.340672:21494949732197:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3f0\n[19085:775:0419/114648.340751:21494949811283:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4511113396446559645\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.340815:21494949883247:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 170024 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.340872:21494949932397:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d410 with delay 500\n[19085:775:0419/114648.340926:21494949986760:INFO:recurring-task.cc(55)] [Retry] Scheduling 169768 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.340979:21494950039189:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d430 with delay 60000\n[19085:775:0419/114648.341027:21494950087801:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d410\n[19085:775:0419/114648.341098:21494950158911:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.341161:21494950221900:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.341306:21494950367058: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: \"4511113396446559645\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.341438:21494950499182:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d4d0 with delay 0\n[19085:775:0419/114648.341518:21494950584407:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d4d0\n[19085:775:0419/114648.341681:21494950742283:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4511113396446559645\" 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[19085:775:0419/114648.341772:21494950833652:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4511113396446559645\"\n[19085:775:0419/114648.341829:21494950889948:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.341889:21494950949984:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 102328 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.341952:21494951012208:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d4f0 with delay 1200000\n[19085:775:0419/114648.342001:21494951061564:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.342152:21494951213340:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.342218:21494951278759:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 83208 with a delay 0, Now = 211419424\n[19085:775:0419/114648.342273:21494951333639:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d710 with delay 0\n[19085:775:0419/114648.342346:21494951406948: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[19085:775:0419/114648.342414:21494951474867:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d710\n[19085:775:0419/114648.342542:21494951604265:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d7d0 with delay 0\n[19085:775:0419/114648.342620:21494951681112:INFO:recurring-task.cc(55)] [Retry] Scheduling 83208 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.342683:21494951744207:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d810 with delay 10000\n[19085:775:0419/114648.342740:21494951800352:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d7d0\n[19085:775:0419/114648.342784:21494951844223:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.342848:21494951916630:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.342961:21494952022908:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000d830 with delay 0\n[19085:775:0419/114648.343019:21494952079599:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000d830\n[19085:775:0419/114648.343170:21494952230717: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[19085:775:0419/114648.343277:21494952337651: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[19085:775:0419/114648.343354:21494952414689:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[19085:775:0419/114648.343523:21494952583601:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000d810\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms)\n[24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[19085:775:0419/114648.344321:21494953382430:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e190 with delay 0\n[19085:775:0419/114648.344387:21494953447742:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.344723:21494953784057:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e810 with delay 0\n[19085:775:0419/114648.344774:21494953834583:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e190\n[19085:775:0419/114648.344828:21494953888867:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e810\n[19085:775:0419/114648.344937:21494953997368:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.345034:21494954094727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e8d0 with delay 0\n[19085:775:0419/114648.345103:21494954163325:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e8d0\n[19085:775:0419/114648.345148:21494954208298:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.345202:21494954263598:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e910 with delay 0\n[19085:775:0419/114648.345250:21494954311002:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e910\n[19085:775:0419/114648.345302:21494954363039:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.345366:21494954427641:INFO:recurring-task.cc(55)] [Startup] Scheduling 192424 with a delay 0, Now = 210919424\n[19085:775:0419/114648.345415:21494954485044:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e930 with delay 0\n[19085:775:0419/114648.345472:21494954532565:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000e930\n[19085:775:0419/114648.345552:21494954613198:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7468174234372051856\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.345617:21494954677985:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 192680 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.345666:21494954726490:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e950 with delay 500\n[19085:775:0419/114648.345722:21494954782349:INFO:recurring-task.cc(55)] [Retry] Scheduling 192424 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.345808:21494954868711:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000e970 with delay 60000\n[19085:775:0419/114648.345865:21494954926927:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000e950\n[19085:775:0419/114648.345938:21494954998890:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.346018:21494955078992:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.346161:21494955222364: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: \"-7468174234372051856\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.346288:21494955349341:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ea10 with delay 0\n[19085:775:0419/114648.346346:21494955406362:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ea10\n[19085:775:0419/114648.346467:21494955528081:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7468174234372051856\" 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[19085:775:0419/114648.346557:21494955624884:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7468174234372051856\"\n[19085:775:0419/114648.346613:21494955674338:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.346683:21494955744091:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 105496 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.346738:21494955798847:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ea30 with delay 1200000\n[19085:775:0419/114648.346801:21494955862143:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.346969:21494956036947:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.347032:21494956092840:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 86472 with a delay 0, Now = 211419424\n[19085:775:0419/114648.347087:21494956147508:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ec50 with delay 0\n[19085:775:0419/114648.347154:21494956214999: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[19085:775:0419/114648.347222:21494956283122:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ec50\n[19085:775:0419/114648.347311:21494956372232:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ed10 with delay 0\n[19085:775:0419/114648.347373:21494956433561:INFO:recurring-task.cc(55)] [Retry] Scheduling 86472 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.347428:21494956488848:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ed50 with delay 10000\n[19085:775:0419/114648.347483:21494956543943:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ed10\n[19085:775:0419/114648.347527:21494956587737:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.347601:21494956662218:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000ed70 with delay 0\n[19085:775:0419/114648.347648:21494956708879:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000ed70\n[19085:775:0419/114648.347728:21494956788802:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[19085:775:0419/114648.347815:21494956876997:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 192680 with a delay 500000, Now = 211469424\n[19085:775:0419/114648.347872:21494956932585:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000ed90 with delay 500\n[19085:775:0419/114648.347924:21494956999971:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 192552 with a delay 60000000, Now = 211469424\n[19085:775:0419/114648.347988:21494957049197:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000edb0 with delay 60000\n[19085:775:0419/114648.348049:21494957109648:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000ed90\n[19085:775:0419/114648.348102:21494957162657:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.348165:21494957226008:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.348225:21494957286051:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19085:775:0419/114648.348389:21494957450250: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[19085:775:0419/114648.348497:21494957558108:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.348566:21494957627531:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000ee50 with delay 0\n[19085:775:0419/114648.348629:21494957689999:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000ee50\n[19085:775:0419/114648.348751:21494957813408: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[19085:775:0419/114648.348856:21494957917519: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[19085:775:0419/114648.348920:21494957980802:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[19085:775:0419/114648.349039:21494958100110:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[19085:775:0419/114648.349222:21494958283384:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000ed50\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[19085:775:0419/114648.350001:21494959062927:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000f8b0 with delay 0\n[19085:775:0419/114648.350077:21494959137928:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.350315:21494959376644:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fdd0 with delay 0\n[19085:775:0419/114648.350372:21494959433610:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000f8b0\n[19085:775:0419/114648.350419:21494959480304:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fdd0\n[19085:775:0419/114648.350495:21494959555979:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.350580:21494959642041:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fe90 with delay 0\n[19085:775:0419/114648.350650:21494959710992:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fe90\n[19085:775:0419/114648.350705:21494959765871:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.350760:21494959821220:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fed0 with delay 0\n[19085:775:0419/114648.350813:21494959874184:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fed0\n[19085:775:0419/114648.350858:21494959918777:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.350919:21494959980704:INFO:recurring-task.cc(55)] [Startup] Scheduling 220840 with a delay 0, Now = 210919424\n[19085:775:0419/114648.350974:21494960035508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000fef0 with delay 0\n[19085:775:0419/114648.351027:21494960088500:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000fef0\n[19085:775:0419/114648.351116:21494960177788:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6874840049619690185\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.351190:21494960251922:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 221096 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.351246:21494960307530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ff10 with delay 500\n[19085:775:0419/114648.351298:21494960359538:INFO:recurring-task.cc(55)] [Retry] Scheduling 220840 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.351346:21494960406891:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ff30 with delay 60000\n[19085:775:0419/114648.351402:21494960462969:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ff10\n[19085:775:0419/114648.351455:21494960516244:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.351524:21494960585400:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.351681:21494960742162: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: \"-6874840049619690185\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.351813:21494960874688:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ffd0 with delay 0\n[19085:775:0419/114648.351864:21494960925512:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ffd0\n[19085:775:0419/114648.351988:21494961049630:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6874840049619690185\" 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[19085:775:0419/114648.352080:21494961140988:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6874840049619690185\"\n[19085:775:0419/114648.352136:21494961197160:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.352194:21494961254868:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 108840 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.352260:21494961321559:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000fff0 with delay 1200000\n[19085:775:0419/114648.352317:21494961378609:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.352505:21494961566687:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.352568:21494961629884:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 91464 with a delay 0, Now = 211419424\n[19085:775:0419/114648.352617:21494961678571:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000010210 with delay 0\n[19085:775:0419/114648.352710:21494961772020: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[19085:775:0419/114648.352773:21494961834808:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000010210\n[19085:775:0419/114648.352865:21494961926652:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000102d0 with delay 0\n[19085:775:0419/114648.352928:21494961988840:INFO:recurring-task.cc(55)] [Retry] Scheduling 91464 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.352999:21494962060965:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000010310 with delay 10000\n[19085:775:0419/114648.353060:21494962121024:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000102d0\n[19085:775:0419/114648.353113:21494962174363:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.353181:21494962242368:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000010330 with delay 0\n[19085:775:0419/114648.353247:21494962308683:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000010330\n[19085:775:0419/114648.353309:21494962370243:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[19085:775:0419/114648.353401:21494962462240:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 221096 with a delay 500000, Now = 211469424\n[19085:775:0419/114648.353451:21494962511967:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000010350 with delay 500\n[19085:775:0419/114648.353514:21494962575685:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 220968 with a delay 60000000, Now = 211469424\n[19085:775:0419/114648.353568:21494962629571:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000010370 with delay 60000\n[19085:775:0419/114648.353629:21494962695921:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000010350\n[19085:775:0419/114648.353684:21494962745139:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.353761:21494962822560:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.353808:21494962868957:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19085:775:0419/114648.353937:21494963005821: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[19085:775:0419/114648.354098:21494963159352:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000010310\n[19085:775:0419/114648.354380:21494963441300:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000ff30\n[19085:775:0419/114648.354438:21494963499717:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x602000010370\n[19085:775:0419/114648.354524:21494963585587: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[19085:775:0419/114648.354572:21494963633779:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[19085:775:0419/114648.354668:21494963728921: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[19085:775:0419/114648.354730:21494963791219:INFO:recurring-task.cc(55)] [Send-info] Scheduling 221096 with a delay 500000, Now = 271469424\n[19085:775:0419/114648.354784:21494963845662:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000010410 with delay 500\n[19085:775:0419/114648.354831:21494963892570:INFO:recurring-task.cc(55)] [Retry] Scheduling 220968 with a delay 60000000, Now = 271469424\n[19085:775:0419/114648.354886:21494963947251:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000010430 with delay 60000\n[19085:775:0419/114648.354951:21494964012884:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x602000010410\n[19085:775:0419/114648.355009:21494964069871:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.355084:21494964153599:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.355140:21494964201245:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19085:775:0419/114648.355304:21494964366291: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 (6 ms)\n[26/28] InvalidationClientImplTest.NetworkTimeouts (6 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[19085:775:0419/114648.356184:21494965246288:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000010d10 with delay 0\n[19085:775:0419/114648.356259:21494965320027:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.356497:21494965559023:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011230 with delay 0\n[19085:775:0419/114648.356555:21494965616472:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000010d10\n[19085:775:0419/114648.356601:21494965662182:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011230\n[19085:775:0419/114648.356690:21494965751983:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.356773:21494965834851:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000112f0 with delay 0\n[19085:775:0419/114648.356834:21494965894844:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000112f0\n[19085:775:0419/114648.356878:21494965939349:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.356934:21494965994909:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011330 with delay 0\n[19085:775:0419/114648.357001:21494966062350:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011330\n[19085:775:0419/114648.357045:21494966106808:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.357107:21494966168239:INFO:recurring-task.cc(55)] [Startup] Scheduling 249768 with a delay 0, Now = 210919424\n[19085:775:0419/114648.357169:21494966231119:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011350 with delay 0\n[19085:775:0419/114648.357229:21494966290041:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011350\n[19085:775:0419/114648.357310:21494966372077:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7118925777268866368\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.357366:21494966427377:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 250024 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.357421:21494966482478:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011370 with delay 500\n[19085:775:0419/114648.357473:21494966534790:INFO:recurring-task.cc(55)] [Retry] Scheduling 249768 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.357521:21494966582099:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011390 with delay 60000\n[19085:775:0419/114648.357577:21494966638624:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011370\n[19085:775:0419/114648.357633:21494966701639:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.357704:21494966765669:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.357843:21494966904739: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: \"-7118925777268866368\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.357984:21494967045742:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011430 with delay 0\n[19085:775:0419/114648.358070:21494967132500:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011430\n[19085:775:0419/114648.358202:21494967264601:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7118925777268866368\" 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[19085:775:0419/114648.358288:21494967349458:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7118925777268866368\"\n[19085:775:0419/114648.358343:21494967403921:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.358406:21494967468038:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 111480 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.358455:21494967516820:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011450 with delay 1200000\n[19085:775:0419/114648.358513:21494967574102:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.358684:21494967745923:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.358752:21494967814020:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 97032 with a delay 0, Now = 211419424\n[19085:775:0419/114648.358818:21494967880540:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011670 with delay 0\n[19085:775:0419/114648.358896:21494967957302: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[19085:775:0419/114648.358964:21494968025123:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011670\n[19085:775:0419/114648.359046:21494968108149:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011730 with delay 0\n[19085:775:0419/114648.359109:21494968170122:INFO:recurring-task.cc(55)] [Retry] Scheduling 97032 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.359165:21494968226423:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000011770 with delay 10000\n[19085:775:0419/114648.359219:21494968280370:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000011730\n[19085:775:0419/114648.359262:21494968323581:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.359334:21494968395348:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.359413:21494968475022:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000011790 with delay 0\n[19085:775:0419/114648.359472:21494968533660:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000011790\n[19085:775:0419/114648.359583:21494968644471: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[19085:775:0419/114648.359711:21494968773183:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000011770\n[19085:775:0419/114648.360036:21494969098161:INFO:invalidation-client-impl_test.cc(477)] Reg manager state: { client_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_summary: { num_registrations: 1 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } }\n[ OK ] InvalidationClientImplTest.NoRegistrationSummary (5 ms)\n[27/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[19085:775:0419/114648.360598:21494969660464:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000011ff0 with delay 0\n[19085:775:0419/114648.360673:21494969734770:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[19085:775:0419/114648.360932:21494969994451:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012510 with delay 0\n[19085:775:0419/114648.360983:21494970044405:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000011ff0\n[19085:775:0419/114648.361052:21494970113500:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012510\n[19085:775:0419/114648.361122:21494970183360:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[19085:775:0419/114648.361203:21494970265105:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000125d0 with delay 0\n[19085:775:0419/114648.361263:21494970324680:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000125d0\n[19085:775:0419/114648.361308:21494970369857:WARNING:invalidation-client-core.cc(961)] Could not read state blob:\n[19085:775:0419/114648.361362:21494970423979:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012610 with delay 0\n[19085:775:0419/114648.361410:21494970471523:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012610\n[19085:775:0419/114648.361454:21494970515360:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[19085:775:0419/114648.361527:21494970588679:INFO:recurring-task.cc(55)] [Startup] Scheduling 271400 with a delay 0, Now = 210919424\n[19085:775:0419/114648.361575:21494970644180:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012630 with delay 0\n[19085:775:0419/114648.361631:21494970692041:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000012630\n[19085:775:0419/114648.361712:21494970773240:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"5965324391524081395\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[19085:775:0419/114648.361780:21494970841741:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 271656 with a delay 500000, Now = 210919424\n[19085:775:0419/114648.361828:21494970889904:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012650 with delay 500\n[19085:775:0419/114648.361882:21494970944083:INFO:recurring-task.cc(55)] [Retry] Scheduling 271400 with a delay 60000000, Now = 210919424\n[19085:775:0419/114648.361945:21494971006845:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000012670 with delay 60000\n[19085:775:0419/114648.361994:21494971055709:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012650\n[19085:775:0419/114648.362047:21494971108579:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.362109:21494971170428:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[19085:775:0419/114648.362256:21494971317868: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: \"5965324391524081395\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[19085:775:0419/114648.362414:21494971476682:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012710 with delay 0\n[19085:775:0419/114648.362476:21494971538282:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012710\n[19085:775:0419/114648.362606:21494971668152:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"5965324391524081395\" 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[19085:775:0419/114648.362712:21494971782588:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"5965324391524081395\"\n[19085:775:0419/114648.362772:21494971833765:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[19085:775:0419/114648.362842:21494971904092:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 113944 with a delay 1200000000, Now = 211419424\n[19085:775:0419/114648.362898:21494971959721:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012730 with delay 1200000\n[19085:775:0419/114648.362947:21494972009078:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[19085:775:0419/114648.363110:21494972185787:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.363182:21494972244683:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 100296 with a delay 0, Now = 211419424\n[19085:775:0419/114648.363244:21494972306365:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012950 with delay 0\n[19085:775:0419/114648.363330:21494972392939: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[19085:775:0419/114648.363392:21494972453843:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012950\n[19085:775:0419/114648.363482:21494972543865:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012a10 with delay 0\n[19085:775:0419/114648.363559:21494972620479:INFO:recurring-task.cc(55)] [Retry] Scheduling 100296 with a delay 10000000, Now = 211419424\n[19085:775:0419/114648.363613:21494972675691:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000012a50 with delay 10000\n[19085:775:0419/114648.363671:21494972732747:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000012a10\n[19085:775:0419/114648.363716:21494972777271:INFO:invalidation-client-core.cc(146)] Write state completed: 1,\n[19085:775:0419/114648.363832:21494972893723:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000012a50\n[19085:775:0419/114648.364104:21494973165863:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x602000012670\n[19085:775:0419/114648.369940:21494979004784:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x602000012730\n[19085:775:0419/114648.370033:21494979096464:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.370110:21494979172362:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[19085:775:0419/114648.370173:21494979235105:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[19085:775:0419/114648.370356:21494979418790: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[19085:775:0419/114648.370420:21494979482624:INFO:recurring-task.cc(55)] [Send-info] Scheduling 271656 with a delay 500000, Now = 1411419424\n[19085:775:0419/114648.370496:21494979558165:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000012a70 with delay 500\n[19085:775:0419/114648.370558:21494979620280:INFO:recurring-task.cc(55)] [Retry] Scheduling 113944 with a delay 1200000000, Now = 1411419424\n[19085:775:0419/114648.370615:21494979676937:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000012a90 with delay 1200000\n[19085:775:0419/114648.370672:21494979733851:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x602000012a70\n[19085:775:0419/114648.370718:21494979779730:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.370804:21494979866342:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[19085:775:0419/114648.370859:21494979921220:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[19085:775:0419/114648.371061:21494980124017: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 (11 ms)\n[28/28] InvalidationClientImplTest.Heartbeats (11 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "8e6aa8e2531ffd5ac2f5cf55835a87d3727643c0", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "444fbd8c19383a11", "server_versions": [ "4267-53b17d5" ], "started_ts": "2019-04-19T18:46:39.029675", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Mac ASan 64 Tests (1)", "buildnumber:52113", "cpu:x86-64", "data:a621f1f4f539098ed18a34fd8300165dca85ac19", "gpu:none", "master:chromium.memory", "name:cacheinvalidation_unittests", "os:Mac-10.13", "pool:Chrome", "priority:25", "project:chromium", "purpose:CI", "purpose:luci", "purpose:post-commit", "service_account:none", "slavename:vm258-m9", "spec_name:chromium.ci:Mac ASan 64 Tests (1)", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:b0a6cb78cd34832b49b843b36f65ec5a7a568a79", "user:None" ], "task_id": "4457710f3684e610" } ] }