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

{ "shards": [ { "bot_dimensions": [ { "key": "caches", "value": [ "swarming_module_cache_vpython" ] }, { "key": "cores", "value": [ "8" ] }, { "key": "cpu", "value": [ "x86", "x86-64", "x86-64-Broadwell_GCE", "x86-64-avx2" ] }, { "key": "gce", "value": [ "1" ] }, { "key": "gpu", "value": [ "none" ] }, { "key": "id", "value": [ "gce-trusty-e833d7b0-us-east1-b-bpnq" ] }, { "key": "image", "value": [ "chrome-trusty-18091700-38cc06ee3ee" ] }, { "key": "inside_docker", "value": [ "0" ] }, { "key": "kvm", "value": [ "1" ] }, { "key": "machine_type", "value": [ "n1-standard-8" ] }, { "key": "os", "value": [ "Linux", "Ubuntu", "Ubuntu-14.04" ] }, { "key": "pool", "value": [ "Chrome" ] }, { "key": "python", "value": [ "2.7.6" ] }, { "key": "server_version", "value": [ "4120-35fcaef" ] }, { "key": "zone", "value": [ "us", "us-east", "us-east1", "us-east1-b" ] } ], "bot_id": "gce-trusty-e833d7b0-us-east1-b-bpnq", "bot_version": "a2700c9ff2d34d10a630c8f28219ec5c0dd7154694274eb9070d5f970cfed06f", "cipd_pins": { "client_package": { "package_name": "infra/tools/cipd/linux-amd64", "version": "a2dqpK39PjGpFdcdw62OAE0JOJJ9n8J_AXpJHmH0QCIC" }, "packages": [ { "package_name": "infra/python/cpython/linux-amd64", "path": ".swarming_module", "version": "46c0c897ca0f053799ee41fd148bb7a47232df47" }, { "package_name": "infra/tools/luci/logdog/butler/linux-amd64", "path": ".swarming_module", "version": "2737ea8ed9b958f4d5aa9ffe106115a649ada241" }, { "package_name": "infra/tools/luci/vpython-native/linux-amd64", "path": ".swarming_module", "version": "OAXVAmcUSrvDygYUrCDzv20LRono9938YOHPu0zKowgC" }, { "package_name": "infra/tools/luci/vpython/linux-amd64", "path": ".swarming_module", "version": "ucaOciwAE9aweCUDOrmSvyiwrjmbywuB0NzAGUXIHjAC" } ] }, "completed_ts": "2019-02-22T20:41:48.600121", "cost_saved_usd": 0.0011353611275308623, "created_ts": "2019-02-22T23:27:02.581185", "deduped_from": "432fc2b6326ac711", "duration": 2.2720470428466797, "modified_ts": "2019-02-22T23:27:02.592100", "name": "cacheinvalidation_unittests/Ubuntu-14.04/7406c47188/Linux TSan Tests/34585", "output": "Additional test environment:\n CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox\n CHROME_HEADLESS=1\n G_SLICE=always-malloc\n LANG=en_US.UTF-8\n NSS_DISABLE_ARENA_FREE_LIST=1\n NSS_DISABLE_UNLOAD=1\n TSAN_OPTIONS=symbolize=1 external_symbolizer_path=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer\nCommand: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioZrmNTn/output.json --no-sandbox\n\nIMPORTANT DEBUGGING NOTE: batches of tests are run inside their\nown process. For debugging a test inside a debugger, use the\n--gtest_filter=<your_test_name> flag along with\n--single-process-tests.\nUsing sharding settings from environment. This is shard 0/1\nUsing 8 parallel jobs.\n[ RUN ] InvalidationClientImplTest.Start\n[7370:7370:0222/124146.263422:401809174:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e90 with delay 0\n[7370:7370:0222/124146.263744:401809494:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.264171:401809923:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d00 with delay 0\n[7370:7370:0222/124146.264249:401810023:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e90\n[7370:7370:0222/124146.264351:401810099:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d00\n[7370:7370:0222/124146.264495:401810245:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.264611:401810361:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ca0 with delay 0\n[7370:7370:0222/124146.264691:401810440:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001ca0\n[7370:7370:0222/124146.264761:401810520:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.264848:401810597:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d00 with delay 0\n[7370:7370:0222/124146.264920:401810668:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d00\n[7370:7370:0222/124146.264994:401810743:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.265072:401810820:INFO:recurring-task.cc(55)] [Startup] Scheduling 7400 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.265141:401810895:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ca0 with delay 0\n[7370:7370:0222/124146.265218:401810966:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001ca0\n[7370:7370:0222/124146.265382:401811131:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"3061020742421774649\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.265466:401811215:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7496 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.265537:401811286:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d00 with delay 500\n[7370:7370:0222/124146.265610:401811358:INFO:recurring-task.cc(55)] [Retry] Scheduling 7400 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.265680:401811429:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d40 with delay 60000\n[7370:7370:0222/124146.265759:401811517:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d00\n[7370:7370:0222/124146.265838:401811586:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.265951:401811699:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.266259:401812039: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: \"3061020742421774649\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.266519:401812268:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d00 with delay 0\n[7370:7370:0222/124146.266596:401812345:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d00\n[7370:7370:0222/124146.266874:401812623:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"3061020742421774649\" 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[7370:7370:0222/124146.266982:401812733:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"3061020742421774649\"\n[7370:7370:0222/124146.267060:401812809:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.267136:401812890:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.267218:401812967:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001cf0 with delay 1200000\n[7370:7370:0222/124146.267294:401813044:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.267524:401813274:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.267604:401813353:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.267678:401813426:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ca0 with delay 0\n[7370:7370:0222/124146.267809:401813558: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[7370:7370:0222/124146.267892:401813639:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001ca0\n[7370:7370:0222/124146.268028:401813777:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001cc0 with delay 0\n[7370:7370:0222/124146.268112:401813860:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.268188:401813939:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e90 with delay 10000\n[7370:7370:0222/124146.268262:401814010:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001cc0\n[7370:7370:0222/124146.268331:401814079:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[ OK ] InvalidationClientImplTest.Start (6 ms)\n[1/28] InvalidationClientImplTest.Start (6 ms)\n[ RUN ] InvalidationClientImplTest.GenerateNonce\n[7370:7370:0222/124146.269362:401815113:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 0\n[7370:7370:0222/124146.269479:401815228:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)\n[2/28] InvalidationClientImplTest.GenerateNonce (1 ms)\n[ RUN ] InvalidationClientImplTest.Register\n[7370:7370:0222/124146.270400:401816151:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d20 with delay 0\n[7370:7370:0222/124146.270519:401816268:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.271001:401816751:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c60 with delay 0\n[7370:7370:0222/124146.271078:401816829:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d20\n[7370:7370:0222/124146.271162:401816909:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001c60\n[7370:7370:0222/124146.271305:401817054:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.271421:401817170:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[7370:7370:0222/124146.271498:401817247:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.271568:401817316:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.271641:401817393:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c60 with delay 0\n[7370:7370:0222/124146.271720:401817471:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001c60\n[7370:7370:0222/124146.271805:401817555:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.271883:401817633:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.271957:401817706:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[7370:7370:0222/124146.272027:401817774:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.272174:401817924:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-2997398207302217324\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.272255:401818007:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7400 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.272328:401818077:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c60 with delay 500\n[7370:7370:0222/124146.272399:401818151:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.272472:401818221:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c80 with delay 60000\n[7370:7370:0222/124146.272549:401818297:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c60\n[7370:7370:0222/124146.272620:401818367:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.272705:401818453:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.273017:401818767: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: \"-2997398207302217324\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.273216:401818967:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c60 with delay 0\n[7370:7370:0222/124146.273294:401819043:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c60\n[7370:7370:0222/124146.273553:401819302:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-2997398207302217324\" 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[7370:7370:0222/124146.273656:401819410:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-2997398207302217324\"\n[7370:7370:0222/124146.273737:401819486:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.273825:401819575:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.273900:401819649:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ac0 with delay 1200000\n[7370:7370:0222/124146.273975:401819724:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.274205:401819954:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.274303:401820052:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.274377:401820126:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001b10 with delay 0\n[7370:7370:0222/124146.274496:401820243: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[7370:7370:0222/124146.274579:401820327:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.274716:401820464:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001970 with delay 0\n[7370:7370:0222/124146.274803:401820552:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.274877:401820626:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d20 with delay 10000\n[7370:7370:0222/124146.274948:401820697:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001970\n[7370:7370:0222/124146.275017:401820765:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.275121:401820870:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001970 with delay 0\n[7370:7370:0222/124146.275202:401820949:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001970\n[7370:7370:0222/124146.275303:401821051:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[7370:7370:0222/124146.275398:401821146:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[7370:7370:0222/124146.275488:401821235:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[7370:7370:0222/124146.275646:401821397:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7400 with a delay 500000, Now = 211469424\n[7370:7370:0222/124146.275721:401821469:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001b10 with delay 500\n[7370:7370:0222/124146.275806:401821555:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7784 with a delay 60000000, Now = 211469424\n[7370:7370:0222/124146.275879:401821629:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001b90 with delay 60000\n[7370:7370:0222/124146.275965:401821712:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.276035:401821784:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.276126:401821880:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.276205:401821953:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[7370:7370:0222/124146.276589:401822339: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[7370:7370:0222/124146.276748:401822496:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.276889:401822639:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400001b10 with delay 0\n[7370:7370:0222/124146.276964:401822712:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.277471:401823220: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[7370:7370:0222/124146.277643:401823395: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[7370:7370:0222/124146.277853:401823602:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[7370:7370:0222/124146.278065:401823813:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[7370:7370:0222/124146.278302:401824050:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[7370:7370:0222/124146.278550:401824298:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001d20\n[ OK ] InvalidationClientImplTest.Register (10 ms)\n[3/28] InvalidationClientImplTest.Register (10 ms)\n[ RUN ] InvalidationClientImplTest.Invalidations\n[7370:7370:0222/124146.280082:401825834:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001dc0 with delay 0\n[7370:7370:0222/124146.280212:401825962:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.280721:401826471:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 0\n[7370:7370:0222/124146.280810:401826562:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001dc0\n[7370:7370:0222/124146.280883:401826631:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001870\n[7370:7370:0222/124146.281023:401826774:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.281136:401826890:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001970 with delay 0\n[7370:7370:0222/124146.281219:401826968:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001970\n[7370:7370:0222/124146.281291:401827041:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.281365:401827113:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 0\n[7370:7370:0222/124146.281436:401827183:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001870\n[7370:7370:0222/124146.281503:401827251:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.281579:401827350:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.281679:401827427:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001970 with delay 0\n[7370:7370:0222/124146.281752:401827508:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001970\n[7370:7370:0222/124146.281903:401827651:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-895007305429650167\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.281983:401827732:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.282052:401827801:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 500\n[7370:7370:0222/124146.282125:401827880:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.282206:401827955:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001fb0 with delay 60000\n[7370:7370:0222/124146.282297:401828046:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001870\n[7370:7370:0222/124146.282369:401828121:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.282458:401828206:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.282755:401828520: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: \"-895007305429650167\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.282954:401828705:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001870 with delay 0\n[7370:7370:0222/124146.283029:401828778:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001870\n[7370:7370:0222/124146.283319:401829069:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-895007305429650167\" 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[7370:7370:0222/124146.283423:401829172:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-895007305429650167\"\n[7370:7370:0222/124146.283500:401829249:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.283580:401829329:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.283655:401829404:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c60 with delay 1200000\n[7370:7370:0222/124146.283733:401829481:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.283963:401829714:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.284042:401829791:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.284115:401829864:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001970 with delay 0\n[7370:7370:0222/124146.284250:401829999: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[7370:7370:0222/124146.284344:401830093:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001970\n[7370:7370:0222/124146.284475:401830225:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c70 with delay 0\n[7370:7370:0222/124146.284558:401830307:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.284629:401830382:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001dc0 with delay 10000\n[7370:7370:0222/124146.284712:401830460:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c70\n[7370:7370:0222/124146.284797:401830547:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.284885:401830633:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.284997:401830746:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001c70 with delay 0\n[7370:7370:0222/124146.285074:401830823:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001c70\n[7370:7370:0222/124146.285547:401831296: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[7370:7370:0222/124146.285731:401831481: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[7370:7370:0222/124146.285911:401831660: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[7370:7370:0222/124146.286128:401831889: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[7370:7370:0222/124146.286361:401832110: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[7370:7370:0222/124146.286518:401832267:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001c70 with delay 0\n[7370:7370:0222/124146.286593:401832340:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001970 with delay 0\n[7370:7370:0222/124146.286665:401832414:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001af0 with delay 0\n[7370:7370:0222/124146.286736:401832489:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400001c70\n[7370:7370:0222/124146.286845:401832597:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7976 with a delay 500000, Now = 211519424\n[7370:7370:0222/124146.286920:401832669:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001870 with delay 500\n[7370:7370:0222/124146.286995:401832743:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400001970\n[7370:7370:0222/124146.287078:401832825:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400001af0\n[7370:7370:0222/124146.287168:401832915:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7b0400001870\n[7370:7370:0222/124146.287239:401832988:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.287339:401833089:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.287412:401833161:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[7370:7370:0222/124146.287861:401833610:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: \"2\" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: \"oid0\" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid1\" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: \"oid2\" } is_known_version: true version: 107 is_trickle_restart: true } } }\n[ OK ] InvalidationClientImplTest.Invalidations (9 ms)\n[4/28] InvalidationClientImplTest.Invalidations (9 ms)\n[ RUN ] InvalidationClientImplTest.ServerRequests\n[7370:7370:0222/124146.289065:401834817:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c90 with delay 0\n[7370:7370:0222/124146.289190:401834940:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.289560:401835310:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[7370:7370:0222/124146.289639:401835389:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001c90\n[7370:7370:0222/124146.289709:401835455:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.289856:401835607:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.289974:401835724:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[7370:7370:0222/124146.290050:401835798:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.290119:401835868:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.290207:401835955:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[7370:7370:0222/124146.290300:401836048:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.290371:401836120:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.290449:401836197:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.290518:401836267:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[7370:7370:0222/124146.290589:401836337:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.290734:401836483:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-1792570820379067765\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.290824:401836573:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.290895:401836642:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 500\n[7370:7370:0222/124146.290965:401836714:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.291034:401836782:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e30 with delay 60000\n[7370:7370:0222/124146.291110:401836858:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.291192:401836941:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.291277:401837026:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.291569:401837318: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: \"-1792570820379067765\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.291751:401837511:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e70 with delay 0\n[7370:7370:0222/124146.291838:401837587:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.292097:401837846:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-1792570820379067765\" 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[7370:7370:0222/124146.292207:401837956:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-1792570820379067765\"\n[7370:7370:0222/124146.292284:401838032:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.292358:401838105:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.292430:401838179:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ee0 with delay 1200000\n[7370:7370:0222/124146.292507:401838255:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.292730:401838479:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.292818:401838567:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.292890:401838639:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001b10 with delay 0\n[7370:7370:0222/124146.293006:401838755: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[7370:7370:0222/124146.293088:401838836:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.293228:401838977:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ef0 with delay 0\n[7370:7370:0222/124146.293307:401839055:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.293379:401839127:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c90 with delay 10000\n[7370:7370:0222/124146.293451:401839199:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001ef0\n[7370:7370:0222/124146.293520:401839268:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.293606:401839354:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.293716:401839465:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001ef0 with delay 0\n[7370:7370:0222/124146.293797:401839545:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001ef0\n[7370:7370:0222/124146.294069:401839818: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[7370:7370:0222/124146.294218:401839967: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[7370:7370:0222/124146.294318:401840068:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[7370:7370:0222/124146.294399:401840148:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 8456 with a delay 500000, Now = 211469424\n[7370:7370:0222/124146.294471:401840220:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001b10 with delay 500\n[7370:7370:0222/124146.294548:401840296:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[7370:7370:0222/124146.295013:401840763: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[7370:7370:0222/124146.295127:401840895:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001b10\n[7370:7370:0222/124146.295223:401840971:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.295342:401841091:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.295418:401841166:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[7370:7370:0222/124146.296038:401841788: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[7370:7370:0222/124146.296334:401842085:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001c90\n[ OK ] InvalidationClientImplTest.ServerRequests (9 ms)\n[5/28] InvalidationClientImplTest.ServerRequests (9 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[7370:7370:0222/124146.297865:401843617:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 0\n[7370:7370:0222/124146.297989:401843739:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.298444:401844195:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[7370:7370:0222/124146.298522:401844270:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000019d0\n[7370:7370:0222/124146.298591:401844338:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.298734:401844482:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.298855:401844604:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002090 with delay 0\n[7370:7370:0222/124146.298936:401844687:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002090\n[7370:7370:0222/124146.299035:401844786:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.299114:401844864:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[7370:7370:0222/124146.299192:401844939:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.299260:401845010:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.299343:401845092:INFO:recurring-task.cc(55)] [Startup] Scheduling 7976 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.299414:401845163:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002090 with delay 0\n[7370:7370:0222/124146.299487:401845234:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002090\n[7370:7370:0222/124146.299628:401845379:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"1737974260796683379\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.299712:401845460:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7592 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.299792:401845539:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 500\n[7370:7370:0222/124146.299866:401845615:INFO:recurring-task.cc(55)] [Retry] Scheduling 7976 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.299935:401845683:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020a0 with delay 60000\n[7370:7370:0222/124146.300012:401845760:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.300081:401845829:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.300170:401845919:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.300465:401846213: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: \"1737974260796683379\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.300648:401846400:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e70 with delay 0\n[7370:7370:0222/124146.300725:401846474:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[7370:7370:0222/124146.300992:401846741:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"1737974260796683379\" 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[7370:7370:0222/124146.301097:401846846:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"1737974260796683379\"\n[7370:7370:0222/124146.301179:401846929:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.301258:401847007:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.301330:401847078:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002030 with delay 1200000\n[7370:7370:0222/124146.301406:401847153:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.301625:401847375:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.301704:401847453:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.301789:401847538:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002090 with delay 0\n[7370:7370:0222/124146.301902:401847649: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[7370:7370:0222/124146.301984:401847734:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002090\n[7370:7370:0222/124146.302116:401847866:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000021d0 with delay 0\n[7370:7370:0222/124146.302204:401847952:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.302289:401848039:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000019d0 with delay 10000\n[7370:7370:0222/124146.302366:401848115:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000021d0\n[7370:7370:0222/124146.302437:401848186:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.302522:401848272:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.302620:401848369:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b04000021d0 with delay 0\n[7370:7370:0222/124146.302696:401848445:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b04000021d0\n[7370:7370:0222/124146.302946:401848695: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[7370:7370:0222/124146.303082:401848830: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[7370:7370:0222/124146.303163:401848911:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[7370:7370:0222/124146.303415:401849163:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b04000019d0\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (7 ms)\n[6/28] InvalidationClientImplTest.IncomingErrorMessage (7 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[7370:7370:0222/124146.304855:401850606:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e10 with delay 0\n[7370:7370:0222/124146.304973:401850723:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.305472:401851221:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 0\n[7370:7370:0222/124146.305549:401851298:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e10\n[7370:7370:0222/124146.305619:401851367:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d10\n[7370:7370:0222/124146.305762:401851523:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.305885:401851636:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001af0 with delay 0\n[7370:7370:0222/124146.305963:401851712:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001af0\n[7370:7370:0222/124146.306033:401851782:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.306108:401851855:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 0\n[7370:7370:0222/124146.306183:401851930:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d10\n[7370:7370:0222/124146.306250:401851999:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.306372:401852123:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.306447:401852195:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001af0 with delay 0\n[7370:7370:0222/124146.306519:401852267:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001af0\n[7370:7370:0222/124146.306664:401852413:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-5131494497641412869\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.306747:401852496:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.306828:401852576:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 500\n[7370:7370:0222/124146.306900:401852649:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.306970:401852718:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 60000\n[7370:7370:0222/124146.307047:401852796:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d10\n[7370:7370:0222/124146.307118:401852865:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.307207:401852955:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.307501:401853251: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: \"-5131494497641412869\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.307684:401853434:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d10 with delay 0\n[7370:7370:0222/124146.307759:401853520:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d10\n[7370:7370:0222/124146.308032:401853781:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-5131494497641412869\" 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[7370:7370:0222/124146.308139:401853893:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-5131494497641412869\"\n[7370:7370:0222/124146.308220:401853969:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.308298:401854048:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.308372:401854120:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001970 with delay 1200000\n[7370:7370:0222/124146.308448:401854197:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.308670:401854419:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.308747:401854496:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.308830:401854578:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001af0 with delay 0\n[7370:7370:0222/124146.308941:401854690: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[7370:7370:0222/124146.309028:401854777:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001af0\n[7370:7370:0222/124146.309163:401854913:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c30 with delay 0\n[7370:7370:0222/124146.309246:401854995:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.309316:401855064:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e10 with delay 10000\n[7370:7370:0222/124146.309386:401855133:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c30\n[7370:7370:0222/124146.309455:401855204:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.309539:401855288:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001c30 with delay 0\n[7370:7370:0222/124146.309609:401855358:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001c30\n[7370:7370:0222/124146.309714:401855464:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[7370:7370:0222/124146.309837:401855586:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7976 with a delay 500000, Now = 211469424\n[7370:7370:0222/124146.309914:401855662:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001af0 with delay 500\n[7370:7370:0222/124146.309989:401855737:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7400 with a delay 60000000, Now = 211469424\n[7370:7370:0222/124146.310058:401855806:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001c70 with delay 60000\n[7370:7370:0222/124146.310139:401855892:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001af0\n[7370:7370:0222/124146.310215:401855965:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.310319:401856068:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.310394:401856143:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[7370:7370:0222/124146.310695:401856444: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[7370:7370:0222/124146.310854:401856603:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.310947:401856697:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400001af0 with delay 0\n[7370:7370:0222/124146.311023:401856771:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001af0\n[7370:7370:0222/124146.311270:401857018: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[7370:7370:0222/124146.311404:401857152: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[7370:7370:0222/124146.311485:401857234:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[7370:7370:0222/124146.311667:401857415:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[7370:7370:0222/124146.311932:401857682:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001e10\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (8 ms)\n[7/28] InvalidationClientImplTest.IncomingAuthErrorMessage (8 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[7370:7370:0222/124146.313411:401859162:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ef0 with delay 0\n[7370:7370:0222/124146.313528:401859278:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.313922:401859673:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 0\n[7370:7370:0222/124146.313999:401859747:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001ef0\n[7370:7370:0222/124146.314069:401859816:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000019d0\n[7370:7370:0222/124146.314216:401859965:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.314344:401860093:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d70 with delay 0\n[7370:7370:0222/124146.314424:401860172:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d70\n[7370:7370:0222/124146.314493:401860243:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.314566:401860314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 0\n[7370:7370:0222/124146.314644:401860393:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000019d0\n[7370:7370:0222/124146.314714:401860464:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.314801:401860550:INFO:recurring-task.cc(55)] [Startup] Scheduling 7880 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.314874:401860623:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d70 with delay 0\n[7370:7370:0222/124146.314946:401860692:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d70\n[7370:7370:0222/124146.315088:401860838:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8382697077735534786\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.315177:401860927:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7688 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.315255:401861004:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 500\n[7370:7370:0222/124146.315328:401861077:INFO:recurring-task.cc(55)] [Retry] Scheduling 7880 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.315405:401861157:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ec0 with delay 60000\n[7370:7370:0222/124146.315486:401861235:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000019d0\n[7370:7370:0222/124146.315556:401861303:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.315638:401861388:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.315952:401861701: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: \"8382697077735534786\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.316136:401861891:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000019d0 with delay 0\n[7370:7370:0222/124146.316217:401861969:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000019d0\n[7370:7370:0222/124146.316582:401862331:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8382697077735534786\" 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[7370:7370:0222/124146.316702:401862452:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8382697077735534786\"\n[7370:7370:0222/124146.316793:401862542:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.316875:401862624:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.316950:401862699:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c60 with delay 1200000\n[7370:7370:0222/124146.317026:401862774:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.317263:401863013:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.317340:401863090:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.317412:401863161:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d70 with delay 0\n[7370:7370:0222/124146.317526:401863274: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[7370:7370:0222/124146.317607:401863356:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d70\n[7370:7370:0222/124146.317740:401863491:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f60 with delay 0\n[7370:7370:0222/124146.317831:401863580:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.317904:401863654:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ef0 with delay 10000\n[7370:7370:0222/124146.317979:401863727:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f60\n[7370:7370:0222/124146.318048:401863797:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.318133:401863889:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001f60 with delay 0\n[7370:7370:0222/124146.318216:401863964:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001f60\n[7370:7370:0222/124146.318328:401864078:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[7370:7370:0222/124146.318442:401864191:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7688 with a delay 500000, Now = 211469424\n[7370:7370:0222/124146.318515:401864264:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001d70 with delay 500\n[7370:7370:0222/124146.318589:401864338:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7496 with a delay 60000000, Now = 211469424\n[7370:7370:0222/124146.318662:401864410:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400002080 with delay 60000\n[7370:7370:0222/124146.318742:401864490:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001d70\n[7370:7370:0222/124146.318825:401864574:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.318911:401864660:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.318983:401864732:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[7370:7370:0222/124146.319294:401865044: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[7370:7370:0222/124146.319552:401865302:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001ef0\n[7370:7370:0222/124146.320164:401865912:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400001ec0\n[7370:7370:0222/124146.320240:401865986:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7b0400002080\n[7370:7370:0222/124146.320354:401866104: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[7370:7370:0222/124146.320433:401866182:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[7370:7370:0222/124146.320602:401866352: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[7370:7370:0222/124146.320688:401866438:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7688 with a delay 500000, Now = 271469424\n[7370:7370:0222/124146.320760:401866519:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400001ec0 with delay 500\n[7370:7370:0222/124146.320845:401866594:INFO:recurring-task.cc(55)] [Retry] Scheduling 7496 with a delay 60000000, Now = 271469424\n[7370:7370:0222/124146.320917:401866666:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400001ef0 with delay 60000\n[7370:7370:0222/124146.320994:401866743:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7b0400001ec0\n[7370:7370:0222/124146.321066:401866815:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.321162:401866911:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.321235:401866984:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[7370:7370:0222/124146.321568:401867317:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"new token\" registration_summary: { num_registrations: 1 registration_digest: \"\\327\\003\\047\\242\\324@\\3740-O\\354\\3229\\352\\000\\231\\340\\204\\224\\323\" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: \"3\" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: \"unit-test\" language: \"C++\" application_info: \"InvClientTest\" } server_registration_summary_requested: true } }\n[ OK ] InvalidationClientImplTest.NetworkTimeouts (10 ms)\n[8/28] InvalidationClientImplTest.NetworkTimeouts (10 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[7370:7370:0222/124146.323328:401869079:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d60 with delay 0\n[7370:7370:0222/124146.323446:401869195:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.323828:401869580:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 0\n[7370:7370:0222/124146.323909:401869657:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d60\n[7370:7370:0222/124146.323978:401869726:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001f00\n[7370:7370:0222/124146.324117:401869867:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.324237:401869988:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[7370:7370:0222/124146.324322:401870070:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[7370:7370:0222/124146.324392:401870141:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.324468:401870216:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 0\n[7370:7370:0222/124146.324538:401870285:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001f00\n[7370:7370:0222/124146.324605:401870353:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.324682:401870430:INFO:recurring-task.cc(55)] [Startup] Scheduling 8456 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.324751:401870510:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[7370:7370:0222/124146.324834:401870581:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[7370:7370:0222/124146.324977:401870726:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"542522992704223664\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.325057:401870807:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8072 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.325128:401870883:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 500\n[7370:7370:0222/124146.325205:401870954:INFO:recurring-task.cc(55)] [Retry] Scheduling 8456 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.325275:401871023:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d90 with delay 60000\n[7370:7370:0222/124146.325349:401871097:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f00\n[7370:7370:0222/124146.325419:401871168:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.325503:401871251:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.325814:401871562: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: \"542522992704223664\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.326001:401871751:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f00 with delay 0\n[7370:7370:0222/124146.326077:401871826:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f00\n[7370:7370:0222/124146.326379:401872127:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"542522992704223664\" 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[7370:7370:0222/124146.326482:401872232:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"542522992704223664\"\n[7370:7370:0222/124146.326561:401872310:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.326635:401872386:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.326711:401872460:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d70 with delay 1200000\n[7370:7370:0222/124146.326796:401872545:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.327017:401872767:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.327101:401872849:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.327178:401872926:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002080 with delay 0\n[7370:7370:0222/124146.327289:401873038: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[7370:7370:0222/124146.327370:401873118:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002080\n[7370:7370:0222/124146.327501:401873251:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f60 with delay 0\n[7370:7370:0222/124146.327580:401873329:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.327657:401873406:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d60 with delay 10000\n[7370:7370:0222/124146.327728:401873477:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f60\n[7370:7370:0222/124146.327806:401873555:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.327895:401873643:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.327979:401873728:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001f60 with delay 0\n[7370:7370:0222/124146.328052:401873801:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001f60\n[7370:7370:0222/124146.328246:401873995: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[7370:7370:0222/124146.328442:401874189:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001d60\n[7370:7370:0222/124146.329063:401874813: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 (7 ms)\n[9/28] InvalidationClientImplTest.NoRegistrationSummary (7 ms)\n[ RUN ] InvalidationClientImplTest.Heartbeats\n[7370:7370:0222/124146.330077:401875828:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d80 with delay 0\n[7370:7370:0222/124146.330199:401875949:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[7370:7370:0222/124146.330595:401876346:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002040 with delay 0\n[7370:7370:0222/124146.330675:401876423:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d80\n[7370:7370:0222/124146.330742:401876489:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002040\n[7370:7370:0222/124146.330891:401876640:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[7370:7370:0222/124146.331000:401876749:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[7370:7370:0222/124146.331077:401876825:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[7370:7370:0222/124146.331146:401876902:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[7370:7370:0222/124146.331225:401876974:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002040 with delay 0\n[7370:7370:0222/124146.331297:401877045:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002040\n[7370:7370:0222/124146.331366:401877116:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[7370:7370:0222/124146.331448:401877196:INFO:recurring-task.cc(55)] [Startup] Scheduling 7784 with a delay 0, Now = 210919424\n[7370:7370:0222/124146.331518:401877268:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[7370:7370:0222/124146.331591:401877337:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[7370:7370:0222/124146.331731:401877481:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-6932775046304240149\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[7370:7370:0222/124146.331822:401877571:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[7370:7370:0222/124146.331891:401877639:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002040 with delay 500\n[7370:7370:0222/124146.331964:401877713:INFO:recurring-task.cc(55)] [Retry] Scheduling 7784 with a delay 60000000, Now = 210919424\n[7370:7370:0222/124146.332033:401877782:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020d0 with delay 60000\n[7370:7370:0222/124146.332109:401877857:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002040\n[7370:7370:0222/124146.332183:401877932:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.332268:401878016:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[7370:7370:0222/124146.332560:401878308: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: \"-6932775046304240149\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[7370:7370:0222/124146.332740:401878490:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002040 with delay 0\n[7370:7370:0222/124146.332823:401878572:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002040\n[7370:7370:0222/124146.333093:401878843:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-6932775046304240149\" 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[7370:7370:0222/124146.333208:401878957:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-6932775046304240149\"\n[7370:7370:0222/124146.333285:401879033:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[7370:7370:0222/124146.333362:401879110:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424\n[7370:7370:0222/124146.333433:401879182:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f60 with delay 1200000\n[7370:7370:0222/124146.333510:401879259:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[7370:7370:0222/124146.333735:401879484:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.333823:401879571:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[7370:7370:0222/124146.333896:401879644:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002080 with delay 0\n[7370:7370:0222/124146.334007:401879755: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[7370:7370:0222/124146.334095:401879843:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002080\n[7370:7370:0222/124146.334229:401879978:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f00 with delay 0\n[7370:7370:0222/124146.334327:401880076:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[7370:7370:0222/124146.334402:401880151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d80 with delay 10000\n[7370:7370:0222/124146.334479:401880228:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f00\n[7370:7370:0222/124146.334548:401880298:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[7370:7370:0222/124146.334753:401880510:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001d80\n[7370:7370:0222/124146.335368:401881116:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b04000020d0\n[7370:7370:0222/124146.347674:401893428:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7b0400001f60\n[7370:7370:0222/124146.347839:401893588:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.347955:401893702:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[7370:7370:0222/124146.348033:401893781:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[7370:7370:0222/124146.348462:401894209: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[7370:7370:0222/124146.348561:401894311:INFO:recurring-task.cc(55)] [Send-info] Scheduling 8456 with a delay 500000, Now = 1411419424\n[7370:7370:0222/124146.348638:401894396:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b04000020d0 with delay 500\n[7370:7370:0222/124146.348728:401894478:INFO:recurring-task.cc(55)] [Retry] Scheduling 1464 with a delay 1200000000, Now = 1411419424\n[7370:7370:0222/124146.348813:401894562:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400001d80 with delay 1200000\n[7370:7370:0222/124146.348894:401894642:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7b04000020d0\n[7370:7370:0222/124146.348967:401894716:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.349081:401894829:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[7370:7370:0222/124146.349160:401894909:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[7370:7370:0222/124146.349678:401895429: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 (21 ms)\n[10/28] InvalidationClientImplTest.Heartbeats (21 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[7373:7373:0222/124146.467976:402013728:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002010 with delay 0\n[7373:7373:0222/124146.468335:402014085:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002010\n[7373:7373:0222/124146.468644:402014393: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[7373:7373:0222/124146.468742:402014493:INFO:recurring-task.cc(55)] [Startup] Scheduling 7400 with a delay 500000, Now = 210919424\n[7373:7373:0222/124146.468831:402014580:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f20 with delay 500\n[7373:7373:0222/124146.468913:402014662:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f20\n[7373:7373:0222/124146.469312:402015061:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: \"1\" } initialize_message: { client_type: 2 nonce: \"unit-test-nonce\" application_client_id: { client_type: 2 client_name: \"unit-test-client-id\" } digest_serialization_type: BYTE_BASED } }\n[ OK ] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[11/28] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[7373:7373:0222/124146.470953:402016704: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[12/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[7373:7373:0222/124146.471721:402017471:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 0\n[7373:7373:0222/124146.471829:402017577:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001cd0 with delay 0\n[7373:7373:0222/124146.471905:402017652:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020d0 with delay 0\n[7373:7373:0222/124146.471987:402017735:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002050 with delay 0\n[7373:7373:0222/124146.472057:402017804:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020e0 with delay 0\n[7373:7373:0222/124146.472127:402017873:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[7373:7373:0222/124146.472535:402018285:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001f00\n[7373:7373:0222/124146.472768:402018526: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[7373:7373:0222/124146.472865:402018615:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7112 with a delay 500000, Now = 210919424\n[7373:7373:0222/124146.472947:402018697:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001380 with delay 500\n[7373:7373:0222/124146.473026:402018772:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001cd0\n[7373:7373:0222/124146.473100:402018848:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000020d0\n[7373:7373:0222/124146.473171:402018917:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002050\n[7373:7373:0222/124146.473238:402018985:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000020e0\n[7373:7373:0222/124146.473312:402019058:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[7373:7373:0222/124146.473420:402019167:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[7373:7373:0222/124146.473501:402019248:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001380\n[7373:7373:0222/124146.473703:402019452:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[7373:7373:0222/124146.474470:402020219: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 (4 ms)\n[13/28] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[7373:7373:0222/124146.477113:402022865: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 (2 ms)\n[14/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[7373:7373:0222/124146.478148:402023899: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[7373:7373:0222/124146.478345:402024094: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[7373:7373:0222/124146.478539:402024287: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[7373:7373:0222/124146.478738:402024486: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[15/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[7373:7373:0222/124146.479691:402025442: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[7373:7373:0222/124146.479954:402025705:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[16/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[7373:7373:0222/124146.480874:402026624: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[17/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[7373:7373:0222/124146.481812:402027562: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[7373:7373:0222/124146.481912:402027660:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002130 with delay 0\n[7373:7373:0222/124146.481983:402027731:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002130\n[7373:7373:0222/124146.482170:402027919: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[7373:7373:0222/124146.482266:402028033:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7784 with a delay 500000, Now = 210919424\n[7373:7373:0222/124146.482358:402028106:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f60 with delay 500\n[7373:7373:0222/124146.482434:402028183:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f60\n[7373:7373:0222/124146.482507:402028256:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (17 ms)\n[18/28] ProtocolHandlerTest.ConfigMessage (17 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[7373:7373:0222/124146.499097:402044848: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[19/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[7373:7373:0222/124146.500059:402045809: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[20/28] ProtocolHandlerTest.TokenMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMissing\n[7372:7372:0222/124146.368316:401914068:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002010 with delay 0\n[7372:7372:0222/124146.368411:401914161:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002010\n[7372:7372:0222/124146.368758:401914517: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[7372:7372:0222/124146.368865:401914614:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7400 with a delay 500000, Now = 210919424\n[7372:7372:0222/124146.368938:401914686:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001fc0 with delay 500\n[7372:7372:0222/124146.369015:401914767:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001fc0\n[7372:7372:0222/124146.369164:401914913:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[7372:7372:0222/124146.369237:401914986:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\n[21/28] ProtocolHandlerTest.TokenMissing (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[7372:7372:0222/124146.370013:401915764:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001fc0 with delay 0\n[7372:7372:0222/124146.370093:401915841:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001fc0\n[7372:7372:0222/124146.370180:401915929:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7112 with a delay 500000, Now = 210919424\n[7372:7372:0222/124146.370254:401916024:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002010 with delay 500\n[7372:7372:0222/124146.370356:401916104:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002010\n[7372:7372:0222/124146.370528:401916277:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[7372:7372:0222/124146.370648:401916400: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[7372:7372:0222/124146.370801:401916550: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[7372:7372:0222/124146.371108:401916858: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[7372:7372:0222/124146.371413:401917164: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 (2 ms)\n[22/28] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[7372:7372:0222/124146.372245:401917996:INFO:protocol-handler.cc(139)] Incoming message: { }\n[7372:7372:0222/124146.372331:401918084:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[7372:7372:0222/124146.372417:401918165:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[23/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[7372:7372:0222/124146.372886:401918636:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -1390824296 with a delay 10000, Now = 0\n[7372:7372:0222/124146.372963:401918711:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000021a0 with delay 10\n[7372:7372:0222/124146.373035:401918781:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.373109:401918858:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[7372:7372:0222/124146.373187:401918936:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 60000, Now = 10000\n[7372:7372:0222/124146.373260:401919009:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b0400002150 with delay 60\n[7372:7372:0222/124146.373331:401919078:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7b0400002150\n[7372:7372:0222/124146.373398:401919145:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[7372:7372:0222/124146.373464:401919210:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 60000, Now = 70000\n[7372:7372:0222/124146.373529:401919277:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7b04000021a0 with delay 60\n[7372:7372:0222/124146.373596:401919343:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.373663:401919410:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[7372:7372:0222/124146.373728:401919475:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 60000, Now = 130000\n[7372:7372:0222/124146.373802:401919548:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7b0400002150 with delay 60\n[7372:7372:0222/124146.373866:401919612:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7b0400002150\n[7372:7372:0222/124146.373930:401919677:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[7372:7372:0222/124146.373996:401919745:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 60000, Now = 190000\n[7372:7372:0222/124146.374064:401919812:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7b04000021a0 with delay 60\n[7372:7372:0222/124146.374130:401919876:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.374196:401919943:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[7372:7372:0222/124146.374261:401920024:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 60000, Now = 250000\n[7372:7372:0222/124146.374344:401920091:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7b0400002150 with delay 60\n[7372:7372:0222/124146.374410:401920156:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7b0400002150\n[7372:7372:0222/124146.374473:401920221:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[7372:7372:0222/124146.374538:401920285:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 60000, Now = 310000\n[7372:7372:0222/124146.374603:401920349:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7b04000021a0 with delay 60\n[7372:7372:0222/124146.374669:401920414:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.374730:401920477:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[7372:7372:0222/124146.374803:401920549:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 60000, Now = 370000\n[7372:7372:0222/124146.374874:401920621:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7b0400002150 with delay 60\n[7372:7372:0222/124146.374941:401920688:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7b0400002150\n[7372:7372:0222/124146.375006:401920753:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (3 ms)\n[24/28] RecurringTaskTest.PeriodicTask (3 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[7372:7372:0222/124146.375670:401921420:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -1390824296 with a delay 10000, Now = 0\n[7372:7372:0222/124146.375748:401921497:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b0400002150 with delay 10\n[7372:7372:0222/124146.375834:401921582:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b0400002150\n[7372:7372:0222/124146.375902:401921650:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[7372:7372:0222/124146.375971:401921719:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 50000, Now = 10000\n[7372:7372:0222/124146.376049:401921798:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000021a0 with delay 50\n[7372:7372:0222/124146.376120:401921867:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.376200:401921947:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[7372:7372:0222/124146.376267:401922015:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 149000, Now = 60000\n[7372:7372:0222/124146.376337:401922084:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7b0400002150 with delay 149\n[7372:7372:0222/124146.376408:401922154:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7b0400002150\n[7372:7372:0222/124146.376473:401922220:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[7372:7372:0222/124146.376539:401922289:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 248000, Now = 210000\n[7372:7372:0222/124146.376609:401922356:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7b04000021a0 with delay 248\n[7372:7372:0222/124146.376681:401922429:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.376749:401922496:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[7372:7372:0222/124146.376823:401922570:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 446000, Now = 460000\n[7372:7372:0222/124146.376891:401922638:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7b0400002150 with delay 446\n[7372:7372:0222/124146.376963:401922711:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7b0400002150\n[7372:7372:0222/124146.377030:401922777:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[7372:7372:0222/124146.377097:401922844:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 842000, Now = 910000\n[7372:7372:0222/124146.377170:401922917:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7b04000021a0 with delay 842\n[7372:7372:0222/124146.377245:401922992:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.377310:401923058:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[7372:7372:0222/124146.377376:401923124:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 1040000, Now = 1760000\n[7372:7372:0222/124146.377443:401923190:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7b0400002150 with delay 1040\n[7372:7372:0222/124146.377520:401923267:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7b0400002150\n[7372:7372:0222/124146.377584:401923330:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[7372:7372:0222/124146.377646:401923395:INFO:recurring-task.cc(55)] [Retry] Scheduling -1390824296 with a delay 1040000, Now = 2800000\n[7372:7372:0222/124146.377713:401923460:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7b04000021a0 with delay 1040\n[7372:7372:0222/124146.377803:401923550:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.377867:401923615:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[25/28] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[7372:7372:0222/124146.378530:401924280:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -1390824368 with a delay 10000, Now = 0\n[7372:7372:0222/124146.378609:401924359:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000021a0 with delay 10\n[7372:7372:0222/124146.378688:401924435:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.378758:401924516:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[7372:7372:0222/124146.378839:401924586:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -1390824368 with a delay 10000, Now = 10000\n[7372:7372:0222/124146.378916:401924664:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000021a0 with delay 10\n[7372:7372:0222/124146.378985:401924732:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.379057:401924803:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (1 ms)\n[26/28] RecurringTaskTest.OneShotTask (1 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[7372:7372:0222/124146.379820:401925570:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7b04000021a0 with delay 920\n[7372:7372:0222/124146.379913:401925662:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.380098:401925847:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7b04000021a0 with delay 45000\n[7372:7372:0222/124146.380649:401926398:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b04000021a0\n[ OK ] ThrottleTest.ThrottlingScripted (1 ms)\n[27/28] ThrottleTest.ThrottlingScripted (1 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[7372:7372:0222/124146.380945:401926694:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000021a0 with delay 990\n[7372:7372:0222/124146.381040:401926789:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.381116:401926863:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.381207:401926955:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.381278:401927025:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.381362:401927109:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.381431:401927179:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.381518:401927265:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.381585:401927332:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.381667:401927414:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.381734:401927479:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.381821:401927567:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.381886:401927632:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7b0400002150 with delay 54000\n[7372:7372:0222/124146.383014:401928786:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.383156:401928932:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.383309:401929081:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.383456:401929227:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.383603:401929375:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.383706:401929453:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.383798:401929545:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.383867:401929613:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.383949:401929697:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.384019:401929765:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.384099:401929845:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.384169:401929915:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.384247:401929993:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.384312:401930059:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7b04000021a0 with delay 54000\n[7372:7372:0222/124146.385423:401931171:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.385506:401931256:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.385597:401931345:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.385668:401931414:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.385748:401931494:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.385824:401931569:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.385905:401931653:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.385973:401931719:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.386054:401931800:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.386118:401931865:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.386204:401931950:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.386269:401932042:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.386382:401932128:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.386447:401932194:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7b0400002150 with delay 54000\n[7372:7372:0222/124146.387527:401933274:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.387604:401933351:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.387704:401933471:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.387822:401933570:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.387909:401933656:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.387979:401933725:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.388058:401933804:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.388129:401933876:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.388218:401933964:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.388282:401934028:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.388364:401934110:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.388431:401934177:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7b0400002150 with delay 1000\n[7372:7372:0222/124146.388512:401934259:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7b0400002150\n[7372:7372:0222/124146.388578:401934326:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7b04000021a0 with delay 54000\n[7372:7372:0222/124146.389703:401935450:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.389790:401935539:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.389880:401935626:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.389947:401935693:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.390035:401935782:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.390102:401935850:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.390191:401935937:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.390257:401936023:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.390363:401936110:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.390430:401936177:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.390513:401936260:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.390580:401936325:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7b04000021a0 with delay 1000\n[7372:7372:0222/124146.390659:401936406:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7b04000021a0\n[7372:7372:0222/124146.390725:401936472:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7b0400002150 with delay 54000\n[7372:7372:0222/124146.391819:401937566:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7b0400002150\n[ OK ] ThrottleTest.ThrottlingStorm (11 ms)\n[28/28] ThrottleTest.ThrottlingStorm (11 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "7b816d3ff59ddb64f05b87e0a5c2d629998d4358", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "432fc2b6326ac711", "server_versions": [ "4120-35fcaef" ], "started_ts": "2019-02-22T20:41:40.207664", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux TSan Tests", "buildnumber:34585", "cpu:x86-64", "data:7406c47188e6812a2358663a72b32bc48be46aad", "gpu:none", "master:chromium.memory", "name:cacheinvalidation_unittests", "os:Ubuntu-14.04", "pool:Chrome", "priority:25", "project:chromium", "purpose:CI", "purpose:luci", "purpose:post-commit", "service_account:none", "slavename:swarm323-c4", "spec_name:chromium.ci:Linux TSan Tests", "stepname:cacheinvalidation_unittests", "swarming.pool.template:none", "swarming.pool.version:276dbb9bccda9d9951255f21c08a952b088764ae", "user:None" ], "task_id": "43305a23c0562210" } ] }