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-west1-a-lgvd" ] }, { "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": [ "4105-f0295a3" ] }, { "key": "zone", "value": [ "us", "us-west", "us-west1", "us-west1-a" ] } ], "bot_id": "gce-trusty-e833d7b0-us-west1-a-lgvd", "bot_version": "067619378aee83df0d9b221730bf7bd600247a566a1619830a6ccab246ac35d4", "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-15T09:06:39.781836", "cost_saved_usd": 0.0008578991213365438, "created_ts": "2019-02-15T09:55:36.102293", "deduped_from": "430939cdb17a8711", "duration": 2.1240949630737305, "modified_ts": "2019-02-15T09:55:36.113753", "name": "cacheinvalidation_unittests/Ubuntu-14.04/20cbf560be/Linux TSan Tests/34207", "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/ioQwLiX1/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[26836:26836:0215/010637.300164:29838607898:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e90 with delay 0\n[26836:26836:0215/010637.300516:29838608242:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.301018:29838608747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d00 with delay 0\n[26836:26836:0215/010637.301107:29838608832:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e90\n[26836:26836:0215/010637.301185:29838608909:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d00\n[26836:26836:0215/010637.301348:29838609074:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.301473:29838609204:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ca0 with delay 0\n[26836:26836:0215/010637.301565:29838609289:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001ca0\n[26836:26836:0215/010637.301641:29838609366:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.301716:29838609441:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d00 with delay 0\n[26836:26836:0215/010637.301790:29838609515:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d00\n[26836:26836:0215/010637.301869:29838609594:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.301947:29838609672:INFO:recurring-task.cc(55)] [Startup] Scheduling 7400 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.302042:29838609767:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ca0 with delay 0\n[26836:26836:0215/010637.302129:29838609853:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001ca0\n[26836:26836:0215/010637.302322:29838610047:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"6757980454570735487\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.302417:29838610141:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7496 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.302498:29838610223:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d00 with delay 500\n[26836:26836:0215/010637.302570:29838610294:INFO:recurring-task.cc(55)] [Retry] Scheduling 7400 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.302652:29838610375:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d40 with delay 60000\n[26836:26836:0215/010637.302734:29838610457:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d00\n[26836:26836:0215/010637.302814:29838610538:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.302933:29838610657:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.303251:29838610976: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: \"6757980454570735487\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.303512:29838611237:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d00 with delay 0\n[26836:26836:0215/010637.303588:29838611312:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d00\n[26836:26836:0215/010637.303887:29838611612:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"6757980454570735487\" 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[26836:26836:0215/010637.304018:29838611744:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"6757980454570735487\"\n[26836:26836:0215/010637.304100:29838611826:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.304183:29838611908:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.304257:29838611987:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001cf0 with delay 1200000\n[26836:26836:0215/010637.304367:29838612093:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.304615:29838612341:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.304698:29838612422:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.304777:29838612504:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ca0 with delay 0\n[26836:26836:0215/010637.304897:29838612624: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[26836:26836:0215/010637.304998:29838612731:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001ca0\n[26836:26836:0215/010637.305160:29838612885:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001cc0 with delay 0\n[26836:26836:0215/010637.305247:29838612972:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.305335:29838613063:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e90 with delay 10000\n[26836:26836:0215/010637.305422:29838613147:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001cc0\n[26836:26836:0215/010637.305496:29838613220: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[26836:26836:0215/010637.306540:29838614267:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 0\n[26836:26836:0215/010637.306677:29838614402: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[26836:26836:0215/010637.307620:29838615347:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d20 with delay 0\n[26836:26836:0215/010637.307740:29838615464:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.308240:29838615966:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c60 with delay 0\n[26836:26836:0215/010637.308346:29838616071:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d20\n[26836:26836:0215/010637.308420:29838616142:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001c60\n[26836:26836:0215/010637.308577:29838616303:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.308711:29838616437:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[26836:26836:0215/010637.308797:29838616524:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.308874:29838616598:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.308958:29838616683:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c60 with delay 0\n[26836:26836:0215/010637.309043:29838616767:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001c60\n[26836:26836:0215/010637.309118:29838616843:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.309203:29838616928:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.309289:29838617014:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[26836:26836:0215/010637.309363:29838617087:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.309513:29838617238:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"9051711001760777033\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.309602:29838617327:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7400 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.309676:29838617408:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c60 with delay 500\n[26836:26836:0215/010637.309759:29838617485:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.309832:29838617557:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c80 with delay 60000\n[26836:26836:0215/010637.309913:29838617637:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c60\n[26836:26836:0215/010637.309991:29838617725:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.310103:29838617828:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.310413:29838618139: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: \"9051711001760777033\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.310603:29838618329:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c60 with delay 0\n[26836:26836:0215/010637.310693:29838618417:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c60\n[26836:26836:0215/010637.310974:29838618700:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"9051711001760777033\" 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[26836:26836:0215/010637.311101:29838618826:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"9051711001760777033\"\n[26836:26836:0215/010637.311187:29838618910:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.311267:29838618997:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.311347:29838619070:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ac0 with delay 1200000\n[26836:26836:0215/010637.311431:29838619155:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.311649:29838619377:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.311734:29838619458:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.311811:29838619536:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001b10 with delay 0\n[26836:26836:0215/010637.311926:29838619650: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[26836:26836:0215/010637.312017:29838619741:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.312158:29838619883:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001970 with delay 0\n[26836:26836:0215/010637.312248:29838619973:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.312371:29838620096:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d20 with delay 10000\n[26836:26836:0215/010637.312448:29838620171:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001970\n[26836:26836:0215/010637.312516:29838620240:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.312619:29838620344:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001970 with delay 0\n[26836:26836:0215/010637.312699:29838620423:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001970\n[26836:26836:0215/010637.312809:29838620534:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[26836:26836:0215/010637.312906:29838620629:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid1\" }, 1\n[26836:26836:0215/010637.312994:29838620726:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid2\" }, 1\n[26836:26836:0215/010637.313165:29838620889:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7400 with a delay 500000, Now = 211469424\n[26836:26836:0215/010637.313254:29838620997:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001b10 with delay 500\n[26836:26836:0215/010637.313350:29838621074:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7784 with a delay 60000000, Now = 211469424\n[26836:26836:0215/010637.313428:29838621152:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001b90 with delay 60000\n[26836:26836:0215/010637.313514:29838621237:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.313589:29838621312:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.313679:29838621403:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.313752:29838621477:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[26836:26836:0215/010637.314147:29838621873: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[26836:26836:0215/010637.314310:29838622035:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.314455:29838622180:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400001b10 with delay 0\n[26836:26836:0215/010637.314539:29838622263:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.315040:29838622765: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[26836:26836:0215/010637.315212:29838622936: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[26836:26836:0215/010637.315410:29838623135:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid0\" } op_type: REGISTER } status: { code: SUCCESS } }\n[26836:26836:0215/010637.315628:29838623352:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid1\" } op_type: REGISTER } status: { code: SUCCESS } }\n[26836:26836:0215/010637.315830:29838623553:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: \"oid2\" } op_type: REGISTER } status: { code: SUCCESS } }\n[26836:26836:0215/010637.316097:29838623822: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[26836:26836:0215/010637.317714:29838625442:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001dc0 with delay 0\n[26836:26836:0215/010637.317837:29838625563:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.318407:29838626134:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 0\n[26836:26836:0215/010637.318486:29838626209:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001dc0\n[26836:26836:0215/010637.318563:29838626285:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001870\n[26836:26836:0215/010637.318701:29838626425:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.318820:29838626550:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001970 with delay 0\n[26836:26836:0215/010637.318928:29838626653:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001970\n[26836:26836:0215/010637.319000:29838626735:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.319090:29838626818:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 0\n[26836:26836:0215/010637.319167:29838626890:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001870\n[26836:26836:0215/010637.319238:29838626962:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.319331:29838627056:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.319416:29838627140:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001970 with delay 0\n[26836:26836:0215/010637.319488:29838627212:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001970\n[26836:26836:0215/010637.319643:29838627368:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"-7915551416381695441\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.319729:29838627458:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.319813:29838627538:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 500\n[26836:26836:0215/010637.319892:29838627621:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.319973:29838627697:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001fb0 with delay 60000\n[26836:26836:0215/010637.320061:29838627786:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001870\n[26836:26836:0215/010637.320135:29838627863:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.320231:29838627956:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.320575:29838628301: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: \"-7915551416381695441\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.320784:29838628511:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001870 with delay 0\n[26836:26836:0215/010637.320866:29838628590:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001870\n[26836:26836:0215/010637.321146:29838628870:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"-7915551416381695441\" 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[26836:26836:0215/010637.321248:29838628972:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"-7915551416381695441\"\n[26836:26836:0215/010637.321332:29838629057:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.321420:29838629151:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.321502:29838629227:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c60 with delay 1200000\n[26836:26836:0215/010637.321596:29838629321:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.321836:29838629562:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.321927:29838629652:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.322013:29838629738:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001970 with delay 0\n[26836:26836:0215/010637.322139:29838629864: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[26836:26836:0215/010637.322228:29838629953:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001970\n[26836:26836:0215/010637.322395:29838630120:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c70 with delay 0\n[26836:26836:0215/010637.322476:29838630199:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.322581:29838630320:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001dc0 with delay 10000\n[26836:26836:0215/010637.322669:29838630393:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c70\n[26836:26836:0215/010637.322738:29838630461:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.322832:29838630556:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.322945:29838630670:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001c70 with delay 0\n[26836:26836:0215/010637.323028:29838630752:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001c70\n[26836:26836:0215/010637.323481:29838631206: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[26836:26836:0215/010637.323644:29838631368: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[26836:26836:0215/010637.323818:29838631543: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[26836:26836:0215/010637.324045:29838631770: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[26836:26836:0215/010637.324242:29838631965: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[26836:26836:0215/010637.324411:29838632136:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001c70 with delay 0\n[26836:26836:0215/010637.324491:29838632214:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001970 with delay 0\n[26836:26836:0215/010637.324561:29838632283:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001af0 with delay 0\n[26836:26836:0215/010637.324627:29838632352:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400001c70\n[26836:26836:0215/010637.324720:29838632444:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7976 with a delay 500000, Now = 211519424\n[26836:26836:0215/010637.324801:29838632524:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400001870 with delay 500\n[26836:26836:0215/010637.324875:29838632598:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400001970\n[26836:26836:0215/010637.324956:29838632678:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400001af0\n[26836:26836:0215/010637.325047:29838632771:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7b0400001870\n[26836:26836:0215/010637.325119:29838632846:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.325223:29838632950:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.325305:29838633030:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[26836:26836:0215/010637.325761:29838633490: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[26836:26836:0215/010637.326937:29838634664:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001c90 with delay 0\n[26836:26836:0215/010637.327062:29838634787:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.327481:29838635208:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[26836:26836:0215/010637.327562:29838635286:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001c90\n[26836:26836:0215/010637.327643:29838635365:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.327787:29838635514:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.327909:29838635633:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[26836:26836:0215/010637.327998:29838635734:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.328083:29838635808:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.328157:29838635919:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[26836:26836:0215/010637.328277:29838636022:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.328375:29838636101:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.328456:29838636181:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.328561:29838636285:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001b10 with delay 0\n[26836:26836:0215/010637.328633:29838636357:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.328791:29838636515:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"7004399550679190298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.328903:29838636629:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.328980:29838636713:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 500\n[26836:26836:0215/010637.329064:29838636788:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.329139:29838636863:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e30 with delay 60000\n[26836:26836:0215/010637.329218:29838636942:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.329296:29838637024:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.329386:29838637119:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.329733:29838637458: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: \"7004399550679190298\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.329933:29838637659:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e70 with delay 0\n[26836:26836:0215/010637.330072:29838637817:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.330379:29838638104:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"7004399550679190298\" 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[26836:26836:0215/010637.330508:29838638234:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"7004399550679190298\"\n[26836:26836:0215/010637.330593:29838638318:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.330673:29838638399:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.330757:29838638484:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ee0 with delay 1200000\n[26836:26836:0215/010637.330837:29838638562:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.331079:29838638804:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.331162:29838638885:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.331242:29838638968:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001b10 with delay 0\n[26836:26836:0215/010637.331518:29838639250: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[26836:26836:0215/010637.331675:29838639403:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.331859:29838639587:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ef0 with delay 0\n[26836:26836:0215/010637.331954:29838639679:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.332065:29838639799:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c90 with delay 10000\n[26836:26836:0215/010637.332156:29838639883:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001ef0\n[26836:26836:0215/010637.332234:29838639957:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.332368:29838640095:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.332482:29838640208:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001ef0 with delay 0\n[26836:26836:0215/010637.332563:29838640289:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001ef0\n[26836:26836:0215/010637.332886:29838640612: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[26836:26836:0215/010637.333071:29838640815: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[26836:26836:0215/010637.333179:29838640906:INFO:protocol-handler.cc(294)] Adding subtree: { }\n[26836:26836:0215/010637.333272:29838641000:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 8456 with a delay 500000, Now = 211469424\n[26836:26836:0215/010637.333353:29838641078:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001b10 with delay 500\n[26836:26836:0215/010637.333435:29838641159:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[26836:26836:0215/010637.333931:29838641657: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[26836:26836:0215/010637.334096:29838641823:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001b10\n[26836:26836:0215/010637.334181:29838641907:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.334317:29838642049:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.334406:29838642131:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[26836:26836:0215/010637.335061:29838642788: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[26836:26836:0215/010637.335400:29838643125:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001c90\n[ OK ] InvalidationClientImplTest.ServerRequests (10 ms)\n[5/28] InvalidationClientImplTest.ServerRequests (10 ms)\n[ RUN ] InvalidationClientImplTest.IncomingErrorMessage\n[26836:26836:0215/010637.337143:29838644872:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 0\n[26836:26836:0215/010637.337271:29838644998:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.337751:29838645478:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[26836:26836:0215/010637.337840:29838645564:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000019d0\n[26836:26836:0215/010637.337914:29838645638:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.338075:29838645806:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.338221:29838645949:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002090 with delay 0\n[26836:26836:0215/010637.338309:29838646033:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002090\n[26836:26836:0215/010637.338384:29838646109:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.338463:29838646189:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 0\n[26836:26836:0215/010637.338537:29838646261:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.338612:29838646338:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.338698:29838646424:INFO:recurring-task.cc(55)] [Startup] Scheduling 7976 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.338782:29838646506:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002090 with delay 0\n[26836:26836:0215/010637.338866:29838646591:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002090\n[26836:26836:0215/010637.339028:29838646754:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4992977183054919326\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.339124:29838646850:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7592 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.339201:29838646926:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e70 with delay 500\n[26836:26836:0215/010637.339279:29838647004:INFO:recurring-task.cc(55)] [Retry] Scheduling 7976 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.339352:29838647077:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020a0 with delay 60000\n[26836:26836:0215/010637.339431:29838647158:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.339507:29838647232:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.339602:29838647327:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.339916:29838647642: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: \"4992977183054919326\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.340144:29838647871:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e70 with delay 0\n[26836:26836:0215/010637.340225:29838647950:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001e70\n[26836:26836:0215/010637.340525:29838648252:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4992977183054919326\" 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[26836:26836:0215/010637.340652:29838648379:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4992977183054919326\"\n[26836:26836:0215/010637.340736:29838648462:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.340822:29838648548:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.340900:29838648623:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002030 with delay 1200000\n[26836:26836:0215/010637.340982:29838648716:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.341249:29838648975:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.341335:29838649060:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.341413:29838649137:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002090 with delay 0\n[26836:26836:0215/010637.341530:29838649256: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[26836:26836:0215/010637.341624:29838649349:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002090\n[26836:26836:0215/010637.341772:29838649499:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000021d0 with delay 0\n[26836:26836:0215/010637.341862:29838649588:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.341937:29838649662:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000019d0 with delay 10000\n[26836:26836:0215/010637.342024:29838649750:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000021d0\n[26836:26836:0215/010637.342103:29838649838:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.342205:29838649931:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.342308:29838650034:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b04000021d0 with delay 0\n[26836:26836:0215/010637.342384:29838650110:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b04000021d0\n[26836:26836:0215/010637.342639:29838650365: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[26836:26836:0215/010637.342800:29838650526: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[26836:26836:0215/010637.342883:29838650608:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message\n[26836:26836:0215/010637.343161:29838650894:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b04000019d0\n[ OK ] InvalidationClientImplTest.IncomingErrorMessage (8 ms)\n[6/28] InvalidationClientImplTest.IncomingErrorMessage (8 ms)\n[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage\n[26836:26836:0215/010637.344841:29838652570:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001e10 with delay 0\n[26836:26836:0215/010637.344970:29838652696:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.345527:29838653255:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 0\n[26836:26836:0215/010637.345617:29838653342:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001e10\n[26836:26836:0215/010637.345697:29838653421:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d10\n[26836:26836:0215/010637.345849:29838653576:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.345976:29838653713:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001af0 with delay 0\n[26836:26836:0215/010637.346082:29838653814:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001af0\n[26836:26836:0215/010637.346164:29838653889:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.346244:29838653970:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 0\n[26836:26836:0215/010637.346319:29838654044:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d10\n[26836:26836:0215/010637.346393:29838654117:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.346473:29838654198:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.346547:29838654272:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001af0 with delay 0\n[26836:26836:0215/010637.346623:29838654347:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001af0\n[26836:26836:0215/010637.346776:29838654503:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"566937034658929240\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.346863:29838654595:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.346948:29838654674:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d10 with delay 500\n[26836:26836:0215/010637.347049:29838654775:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.347128:29838654852:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001870 with delay 60000\n[26836:26836:0215/010637.347212:29838654937:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d10\n[26836:26836:0215/010637.347286:29838655010:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.347377:29838655104:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.347688:29838655421: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: \"566937034658929240\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.347904:29838655631:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d10 with delay 0\n[26836:26836:0215/010637.347983:29838655720:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d10\n[26836:26836:0215/010637.348287:29838656029:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"566937034658929240\" 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[26836:26836:0215/010637.348416:29838656142:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"566937034658929240\"\n[26836:26836:0215/010637.348503:29838656228:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.348587:29838656315:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.348666:29838656392:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001970 with delay 1200000\n[26836:26836:0215/010637.348750:29838656474:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.349077:29838656809:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.349167:29838656892:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.349246:29838656975:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001af0 with delay 0\n[26836:26836:0215/010637.349371:29838657096: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[26836:26836:0215/010637.349464:29838657189:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001af0\n[26836:26836:0215/010637.349611:29838657337:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c30 with delay 0\n[26836:26836:0215/010637.349699:29838657425:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.349775:29838657501:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001e10 with delay 10000\n[26836:26836:0215/010637.349851:29838657577:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001c30\n[26836:26836:0215/010637.349930:29838657656:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.350030:29838657756:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001c30 with delay 0\n[26836:26836:0215/010637.350110:29838657834:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001c30\n[26836:26836:0215/010637.350214:29838657939:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[26836:26836:0215/010637.350331:29838658057:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7976 with a delay 500000, Now = 211469424\n[26836:26836:0215/010637.350407:29838658136:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001af0 with delay 500\n[26836:26836:0215/010637.350495:29838658221:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7400 with a delay 60000000, Now = 211469424\n[26836:26836:0215/010637.350570:29838658300:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001c70 with delay 60000\n[26836:26836:0215/010637.350661:29838658387:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001af0\n[26836:26836:0215/010637.350737:29838658462:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.350828:29838658553:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.350907:29838658633:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[26836:26836:0215/010637.351233:29838658963: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[26836:26836:0215/010637.351390:29838659117:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.351497:29838659227:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400001af0 with delay 0\n[26836:26836:0215/010637.351578:29838659307:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001af0\n[26836:26836:0215/010637.351833:29838659559: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[26836:26836:0215/010637.351982:29838659716: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[26836:26836:0215/010637.352075:29838659806:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message\n[26836:26836:0215/010637.352361:29838660093:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects\n[26836:26836:0215/010637.352685:29838660410:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001e10\n[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (9 ms)\n[7/28] InvalidationClientImplTest.IncomingAuthErrorMessage (9 ms)\n[ RUN ] InvalidationClientImplTest.NetworkTimeouts\n[26836:26836:0215/010637.354306:29838662033:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ef0 with delay 0\n[26836:26836:0215/010637.354429:29838662155:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.354895:29838662622:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 0\n[26836:26836:0215/010637.354975:29838662700:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001ef0\n[26836:26836:0215/010637.355061:29838662785:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000019d0\n[26836:26836:0215/010637.355214:29838662939:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.355346:29838663071:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d70 with delay 0\n[26836:26836:0215/010637.355443:29838663170:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d70\n[26836:26836:0215/010637.355520:29838663245:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.355606:29838663334:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 0\n[26836:26836:0215/010637.355684:29838663409:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000019d0\n[26836:26836:0215/010637.355760:29838663484:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.355840:29838663566:INFO:recurring-task.cc(55)] [Startup] Scheduling 7880 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.355918:29838663644:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d70 with delay 0\n[26836:26836:0215/010637.355991:29838663727:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d70\n[26836:26836:0215/010637.356163:29838663889:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"8438101941983949331\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.356248:29838663974:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7688 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.356343:29838664068:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000019d0 with delay 500\n[26836:26836:0215/010637.356418:29838664143:INFO:recurring-task.cc(55)] [Retry] Scheduling 7880 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.356499:29838664223:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001ec0 with delay 60000\n[26836:26836:0215/010637.356579:29838664306:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000019d0\n[26836:26836:0215/010637.356659:29838664384:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.356747:29838664475:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.357065:29838664796: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: \"8438101941983949331\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.357349:29838665075:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000019d0 with delay 0\n[26836:26836:0215/010637.357432:29838665157:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000019d0\n[26836:26836:0215/010637.357704:29838665431:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"8438101941983949331\" 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[26836:26836:0215/010637.357812:29838665538:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"8438101941983949331\"\n[26836:26836:0215/010637.357897:29838665622:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.357978:29838665726:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.358084:29838665815:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001c60 with delay 1200000\n[26836:26836:0215/010637.358170:29838665897:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.358418:29838666146:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.358510:29838666236:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.358587:29838666315:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d70 with delay 0\n[26836:26836:0215/010637.358711:29838666437: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[26836:26836:0215/010637.358801:29838666527:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001d70\n[26836:26836:0215/010637.358942:29838666668:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f60 with delay 0\n[26836:26836:0215/010637.359036:29838666761:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.359120:29838666846:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001ef0 with delay 10000\n[26836:26836:0215/010637.359196:29838666922:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f60\n[26836:26836:0215/010637.359271:29838666996:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.359363:29838667088:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001f60 with delay 0\n[26836:26836:0215/010637.359480:29838667206:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001f60\n[26836:26836:0215/010637.359588:29838667316:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: \"oid0\" }, 1\n[26836:26836:0215/010637.359710:29838667436:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7688 with a delay 500000, Now = 211469424\n[26836:26836:0215/010637.359786:29838667511:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001d70 with delay 500\n[26836:26836:0215/010637.359864:29838667588:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7496 with a delay 60000000, Now = 211469424\n[26836:26836:0215/010637.359937:29838667663:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400002080 with delay 60000\n[26836:26836:0215/010637.360037:29838667763:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400001d70\n[26836:26836:0215/010637.360120:29838667846:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.360222:29838667952:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.360319:29838668045:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[26836:26836:0215/010637.360643:29838668369: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[26836:26836:0215/010637.360906:29838668633:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001ef0\n[26836:26836:0215/010637.361517:29838669241:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400001ec0\n[26836:26836:0215/010637.361599:29838669323:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7b0400002080\n[26836:26836:0215/010637.361736:29838669461: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[26836:26836:0215/010637.361818:29838669544:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true\n[26836:26836:0215/010637.362019:29838669748: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[26836:26836:0215/010637.362116:29838669840:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7688 with a delay 500000, Now = 271469424\n[26836:26836:0215/010637.362191:29838669917:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400001ec0 with delay 500\n[26836:26836:0215/010637.362352:29838670079:INFO:recurring-task.cc(55)] [Retry] Scheduling 7496 with a delay 60000000, Now = 271469424\n[26836:26836:0215/010637.362428:29838670154:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400001ef0 with delay 60000\n[26836:26836:0215/010637.362513:29838670237:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7b0400001ec0\n[26836:26836:0215/010637.362593:29838670320:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.362693:29838670419:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.362797:29838670523:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[26836:26836:0215/010637.363158:29838670889: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 (11 ms)\n[8/28] InvalidationClientImplTest.NetworkTimeouts (11 ms)\n[ RUN ] InvalidationClientImplTest.NoRegistrationSummary\n[26836:26836:0215/010637.364954:29838672683:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d60 with delay 0\n[26836:26836:0215/010637.365095:29838672822:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.365495:29838673222:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 0\n[26836:26836:0215/010637.365578:29838673307:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d60\n[26836:26836:0215/010637.365658:29838673381:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001f00\n[26836:26836:0215/010637.365803:29838673529:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.365925:29838673651:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[26836:26836:0215/010637.366016:29838673741:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[26836:26836:0215/010637.366096:29838673822:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.366177:29838673901:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 0\n[26836:26836:0215/010637.366251:29838673976:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001f00\n[26836:26836:0215/010637.366325:29838674052:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.366407:29838674132:INFO:recurring-task.cc(55)] [Startup] Scheduling 8456 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.366480:29838674207:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[26836:26836:0215/010637.366564:29838674288:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[26836:26836:0215/010637.366713:29838674440:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"2908906244498920913\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.366799:29838674524:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8072 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.366871:29838674598:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 500\n[26836:26836:0215/010637.366950:29838674674:INFO:recurring-task.cc(55)] [Retry] Scheduling 8456 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.367031:29838674756:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d90 with delay 60000\n[26836:26836:0215/010637.367120:29838674844:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f00\n[26836:26836:0215/010637.367194:29838674920:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.367289:29838675015:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.367639:29838675379: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: \"2908906244498920913\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.367863:29838675590:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f00 with delay 0\n[26836:26836:0215/010637.367942:29838675666:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f00\n[26836:26836:0215/010637.368232:29838675958:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"2908906244498920913\" 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[26836:26836:0215/010637.368364:29838676090:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"2908906244498920913\"\n[26836:26836:0215/010637.368448:29838676175:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.368533:29838676259:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.368613:29838676339:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d70 with delay 1200000\n[26836:26836:0215/010637.368697:29838676421:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.368949:29838676675:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.369039:29838676764:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.369122:29838676847:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002080 with delay 0\n[26836:26836:0215/010637.369241:29838676966: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[26836:26836:0215/010637.369332:29838677057:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002080\n[26836:26836:0215/010637.369479:29838677205:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f60 with delay 0\n[26836:26836:0215/010637.369565:29838677293:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.369645:29838677371:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d60 with delay 10000\n[26836:26836:0215/010637.369720:29838677446:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f60\n[26836:26836:0215/010637.369797:29838677523:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.369889:29838677614:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.370025:29838677752:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400001f60 with delay 0\n[26836:26836:0215/010637.370107:29838677833:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400001f60\n[26836:26836:0215/010637.370308:29838678034: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[26836:26836:0215/010637.370527:29838678253:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001d60\n[26836:26836:0215/010637.371207:29838678934: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[26836:26836:0215/010637.372375:29838680104:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001d80 with delay 0\n[26836:26836:0215/010637.372500:29838680226:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: \"clientName\" }, \"\", <RunState 1>\n[26836:26836:0215/010637.372963:29838680690:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002040 with delay 0\n[26836:26836:0215/010637.373055:29838680781:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001d80\n[26836:26836:0215/010637.373134:29838680858:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002040\n[26836:26836:0215/010637.373282:29838681007:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }\n[26836:26836:0215/010637.373400:29838681126:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[26836:26836:0215/010637.373485:29838681208:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[26836:26836:0215/010637.373556:29838681282:WARNING:invalidation-client-core.cc(961)] Could not read state blob: \n[26836:26836:0215/010637.373636:29838681362:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002040 with delay 0\n[26836:26836:0215/010637.373714:29838681438:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002040\n[26836:26836:0215/010637.373785:29838681510:INFO:invalidation-client-core.cc(351)] Starting with no previous state\n[26836:26836:0215/010637.373865:29838681592:INFO:recurring-task.cc(55)] [Startup] Scheduling 7784 with a delay 0, Now = 210919424\n[26836:26836:0215/010637.373943:29838681667:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[26836:26836:0215/010637.374024:29838681750:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[26836:26836:0215/010637.374184:29838681910:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: \"4704095751543131842\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED }\n[26836:26836:0215/010637.374274:29838681999:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424\n[26836:26836:0215/010637.374352:29838682077:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002040 with delay 500\n[26836:26836:0215/010637.374426:29838682152:INFO:recurring-task.cc(55)] [Retry] Scheduling 7784 with a delay 60000000, Now = 210919424\n[26836:26836:0215/010637.374503:29838682227:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020d0 with delay 60000\n[26836:26836:0215/010637.374581:29838682307:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002040\n[26836:26836:0215/010637.374656:29838682381:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.374747:29838682472:INFO:invalidation-client-core.cc(488)] Return client token = \"\"\n[26836:26836:0215/010637.375066:29838682797: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: \"4704095751543131842\" application_client_id: { client_type: 2 client_name: \"clientName\" } digest_serialization_type: BYTE_BASED } }\n[26836:26836:0215/010637.375267:29838682993:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002040 with delay 0\n[26836:26836:0215/010637.375351:29838683077:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002040\n[26836:26836:0215/010637.375627:29838683352:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"4704095751543131842\" 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[26836:26836:0215/010637.375733:29838683459:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: \"4704095751543131842\"\n[26836:26836:0215/010637.375816:29838683541:INFO:invalidation-client-core.cc(591)] New token being assigned at client: \"new token\", Old = \"\"\n[26836:26836:0215/010637.375894:29838683620:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424\n[26836:26836:0215/010637.375973:29838683697:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f60 with delay 1200000\n[26836:26836:0215/010637.376062:29838683787:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready\n[26836:26836:0215/010637.376319:29838684047:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.376402:29838684130:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424\n[26836:26836:0215/010637.376497:29838684223:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400002080 with delay 0\n[26836:26836:0215/010637.376629:29838684355: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[26836:26836:0215/010637.376718:29838684444:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002080\n[26836:26836:0215/010637.376855:29838684580:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001f00 with delay 0\n[26836:26836:0215/010637.376940:29838684666:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424\n[26836:26836:0215/010637.377031:29838684759:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400001d80 with delay 10000\n[26836:26836:0215/010637.377114:29838684839:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f00\n[26836:26836:0215/010637.377187:29838684911:INFO:invalidation-client-core.cc(146)] Write state completed: 1, \n[26836:26836:0215/010637.377395:29838685121:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400001d80\n[26836:26836:0215/010637.377981:29838685716:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b04000020d0\n[26836:26836:0215/010637.390188:29838697919:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7b0400001f60\n[26836:26836:0215/010637.390350:29838698076:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.390478:29838698210:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: \"clientName\" }, \"new token\", <RunState 2>\n[26836:26836:0215/010637.390571:29838698299:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false\n[26836:26836:0215/010637.391041:29838698768: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[26836:26836:0215/010637.391161:29838698894:INFO:recurring-task.cc(55)] [Send-info] Scheduling 8456 with a delay 500000, Now = 1411419424\n[26836:26836:0215/010637.391253:29838698979:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b04000020d0 with delay 500\n[26836:26836:0215/010637.391339:29838699066:INFO:recurring-task.cc(55)] [Retry] Scheduling 1464 with a delay 1200000000, Now = 1411419424\n[26836:26836:0215/010637.391420:29838699146:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400001d80 with delay 1200000\n[26836:26836:0215/010637.391506:29838699230:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7b04000020d0\n[26836:26836:0215/010637.391582:29838699308:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.391717:29838699443:INFO:invalidation-client-core.cc(488)] Return client token = \"new token\"\n[26836:26836:0215/010637.391796:29838699520:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"new token\"\n[26836:26836:0215/010637.392378:29838700105: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 (22 ms)\n[10/28] InvalidationClientImplTest.Heartbeats (22 ms)\n[ RUN ] ProtocolHandlerTest.TokenMissing\n[26838:26838:0215/010637.408031:29838715763:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002010 with delay 0\n[26838:26838:0215/010637.408136:29838715863:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002010\n[26838:26838:0215/010637.408535:29838716262: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[26838:26838:0215/010637.408645:29838716372:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7400 with a delay 500000, Now = 210919424\n[26838:26838:0215/010637.408724:29838716450:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001fc0 with delay 500\n[26838:26838:0215/010637.408805:29838716529:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001fc0\n[26838:26838:0215/010637.408959:29838716684:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }\n[26838:26838:0215/010637.409043:29838716768:WARNING:protocol-handler.cc(313)] Unable to build message\n[ OK ] ProtocolHandlerTest.TokenMissing (2 ms)\n[11/28] ProtocolHandlerTest.TokenMissing (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage\n[26838:26838:0215/010637.409905:29838717632:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001fc0 with delay 0\n[26838:26838:0215/010637.409992:29838717732:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001fc0\n[26838:26838:0215/010637.410105:29838717831:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7112 with a delay 500000, Now = 210919424\n[26838:26838:0215/010637.410187:29838717917:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002010 with delay 500\n[26838:26838:0215/010637.410275:29838718004:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400002010\n[26838:26838:0215/010637.410457:29838718182:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[26838:26838:0215/010637.410589:29838718314: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[26838:26838:0215/010637.410731:29838718456: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[26838:26838:0215/010637.411066:29838718792: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[26838:26838:0215/010637.411391:29838719129: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[12/28] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage\n[26838:26838:0215/010637.412253:29838719980:INFO:protocol-handler.cc(139)] Incoming message: { }\n[26838:26838:0215/010637.412359:29838720084:ERROR:ticl-message-validator.cc(361)] required field header missing from { }\n[26838:26838:0215/010637.412440:29838720164:ERROR:protocol-handler.cc(145)] Received invalid message: { }\n[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[13/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)\n[ RUN ] RecurringTaskTest.PeriodicTask\n[26838:26838:0215/010637.412940:29838720667:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -1348595288 with a delay 10000, Now = 0\n[26838:26838:0215/010637.413043:29838720769:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000021a0 with delay 10\n[26838:26838:0215/010637.413123:29838720847:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.413195:29838720921:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[26838:26838:0215/010637.413273:29838720997:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 60000, Now = 10000\n[26838:26838:0215/010637.413356:29838721082:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b0400002150 with delay 60\n[26838:26838:0215/010637.413433:29838721157:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7b0400002150\n[26838:26838:0215/010637.413501:29838721225:INFO:recurring-task_test.cc(71)] (70000) Task running: 2\n[26838:26838:0215/010637.413569:29838721293:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 60000, Now = 70000\n[26838:26838:0215/010637.413638:29838721362:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7b04000021a0 with delay 60\n[26838:26838:0215/010637.413707:29838721431:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.413774:29838721497:INFO:recurring-task_test.cc(71)] (130000) Task running: 3\n[26838:26838:0215/010637.413843:29838721566:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 60000, Now = 130000\n[26838:26838:0215/010637.413910:29838721633:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7b0400002150 with delay 60\n[26838:26838:0215/010637.413979:29838721711:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7b0400002150\n[26838:26838:0215/010637.414054:29838721777:INFO:recurring-task_test.cc(71)] (190000) Task running: 4\n[26838:26838:0215/010637.414121:29838721844:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 60000, Now = 190000\n[26838:26838:0215/010637.414188:29838721911:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7b04000021a0 with delay 60\n[26838:26838:0215/010637.414256:29838721980:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.414323:29838722052:INFO:recurring-task_test.cc(71)] (250000) Task running: 5\n[26838:26838:0215/010637.414396:29838722118:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 60000, Now = 250000\n[26838:26838:0215/010637.414461:29838722184:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7b0400002150 with delay 60\n[26838:26838:0215/010637.414529:29838722251:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7b0400002150\n[26838:26838:0215/010637.414593:29838722317:INFO:recurring-task_test.cc(71)] (310000) Task running: 6\n[26838:26838:0215/010637.414659:29838722382:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 60000, Now = 310000\n[26838:26838:0215/010637.414725:29838722448:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7b04000021a0 with delay 60\n[26838:26838:0215/010637.414793:29838722515:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.414865:29838722590:INFO:recurring-task_test.cc(71)] (370000) Task running: 7\n[26838:26838:0215/010637.414934:29838722658:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 60000, Now = 370000\n[26838:26838:0215/010637.415010:29838722733:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7b0400002150 with delay 60\n[26838:26838:0215/010637.415078:29838722804:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7b0400002150\n[26838:26838:0215/010637.415147:29838722871:INFO:recurring-task_test.cc(71)] (430000) Task running: 8\n[ OK ] RecurringTaskTest.PeriodicTask (3 ms)\n[14/28] RecurringTaskTest.PeriodicTask (3 ms)\n[ RUN ] RecurringTaskTest.ExponentialBackoffTask\n[26838:26838:0215/010637.415822:29838723569:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -1348595288 with a delay 10000, Now = 0\n[26838:26838:0215/010637.415941:29838723667:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b0400002150 with delay 10\n[26838:26838:0215/010637.416026:29838723751:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b0400002150\n[26838:26838:0215/010637.416110:29838723835:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[26838:26838:0215/010637.416183:29838723907:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 50000, Now = 10000\n[26838:26838:0215/010637.416255:29838723979:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000021a0 with delay 50\n[26838:26838:0215/010637.416356:29838724080:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.416424:29838724148:INFO:recurring-task_test.cc(71)] (60000) Task running: 2\n[26838:26838:0215/010637.416493:29838724220:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 149000, Now = 60000\n[26838:26838:0215/010637.416565:29838724288:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7b0400002150 with delay 149\n[26838:26838:0215/010637.416647:29838724370:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7b0400002150\n[26838:26838:0215/010637.416716:29838724440:INFO:recurring-task_test.cc(71)] (210000) Task running: 3\n[26838:26838:0215/010637.416786:29838724509:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 248000, Now = 210000\n[26838:26838:0215/010637.416859:29838724583:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7b04000021a0 with delay 248\n[26838:26838:0215/010637.416932:29838724655:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.417007:29838724731:INFO:recurring-task_test.cc(71)] (460000) Task running: 4\n[26838:26838:0215/010637.417084:29838724808:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 446000, Now = 460000\n[26838:26838:0215/010637.417160:29838724884:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7b0400002150 with delay 446\n[26838:26838:0215/010637.417237:29838724963:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7b0400002150\n[26838:26838:0215/010637.417313:29838725035:INFO:recurring-task_test.cc(71)] (910000) Task running: 5\n[26838:26838:0215/010637.417386:29838725109:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 842000, Now = 910000\n[26838:26838:0215/010637.417456:29838725180:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7b04000021a0 with delay 842\n[26838:26838:0215/010637.417535:29838725257:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.417600:29838725322:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6\n[26838:26838:0215/010637.417666:29838725389:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 1040000, Now = 1760000\n[26838:26838:0215/010637.417734:29838725458:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7b0400002150 with delay 1040\n[26838:26838:0215/010637.417811:29838725534:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7b0400002150\n[26838:26838:0215/010637.417883:29838725606:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7\n[26838:26838:0215/010637.417949:29838725672:INFO:recurring-task.cc(55)] [Retry] Scheduling -1348595288 with a delay 1040000, Now = 2800000\n[26838:26838:0215/010637.418025:29838725760:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7b04000021a0 with delay 1040\n[26838:26838:0215/010637.418114:29838725857:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.418199:29838725921:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8\n[ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[15/28] RecurringTaskTest.ExponentialBackoffTask (3 ms)\n[ RUN ] RecurringTaskTest.OneShotTask\n[26838:26838:0215/010637.418827:29838726557:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -1348595360 with a delay 10000, Now = 0\n[26838:26838:0215/010637.418914:29838726639:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000021a0 with delay 10\n[26838:26838:0215/010637.418989:29838726725:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.419073:29838726798:INFO:recurring-task_test.cc(71)] (10000) Task running: 1\n[26838:26838:0215/010637.419157:29838726880:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -1348595360 with a delay 10000, Now = 10000\n[26838:26838:0215/010637.419227:29838726950:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000021a0 with delay 10\n[26838:26838:0215/010637.419294:29838727017:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.419370:29838727095:INFO:recurring-task_test.cc(71)] (20000) Task running: 2\n[ OK ] RecurringTaskTest.OneShotTask (1 ms)\n[16/28] RecurringTaskTest.OneShotTask (1 ms)\n[ RUN ] ThrottleTest.ThrottlingScripted\n[26838:26838:0215/010637.420121:29838727848:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7b04000021a0 with delay 920\n[26838:26838:0215/010637.420228:29838727953:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.420447:29838728172:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7b04000021a0 with delay 45000\n[26838:26838:0215/010637.420989:29838728722:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b04000021a0\n[ OK ] ThrottleTest.ThrottlingScripted (1 ms)\n[17/28] ThrottleTest.ThrottlingScripted (1 ms)\n[ RUN ] ThrottleTest.ThrottlingStorm\n[26838:26838:0215/010637.421294:29838729022:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000021a0 with delay 990\n[26838:26838:0215/010637.421402:29838729127:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.421482:29838729206:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.421568:29838729291:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.421639:29838729362:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.421726:29838729450:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.421797:29838729521:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.421883:29838729618:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.421961:29838729683:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.422050:29838729772:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.422115:29838729857:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.422219:29838729942:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.422296:29838730020:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7b0400002150 with delay 54000\n[26838:26838:0215/010637.423443:29838731168:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.423527:29838731251:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.423615:29838731339:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.423686:29838731410:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.423774:29838731497:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.423845:29838731568:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.423929:29838731651:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.424006:29838731729:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.424089:29838731812:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.424157:29838731880:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.424247:29838731970:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.424329:29838732058:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.424422:29838732147:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.424493:29838732217:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7b04000021a0 with delay 54000\n[26838:26838:0215/010637.425586:29838733310:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.425666:29838733391:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.425753:29838733476:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.425821:29838733546:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.425906:29838733628:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.425973:29838733695:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.426063:29838733785:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.426130:29838733852:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.426211:29838733935:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.426281:29838734003:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.426367:29838734090:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.426434:29838734156:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.426514:29838734247:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.426590:29838734312:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7b0400002150 with delay 54000\n[26838:26838:0215/010637.427692:29838735417:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.427771:29838735495:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.427875:29838735598:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.427951:29838735674:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.428056:29838735797:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.428144:29838735866:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.428227:29838735948:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.428292:29838736053:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.428417:29838736140:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.428486:29838736208:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.428568:29838736291:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.428647:29838736368:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7b0400002150 with delay 1000\n[26838:26838:0215/010637.428725:29838736447:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7b0400002150\n[26838:26838:0215/010637.428797:29838736520:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7b04000021a0 with delay 54000\n[26838:26838:0215/010637.429892:29838737617:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.429970:29838737693:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.430078:29838737802:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.430148:29838737870:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.430229:29838737950:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.430294:29838738015:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.430377:29838738099:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.430462:29838738184:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.430543:29838738266:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.430612:29838738334:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.430694:29838738416:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.430760:29838738482:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7b04000021a0 with delay 1000\n[26838:26838:0215/010637.430842:29838738565:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7b04000021a0\n[26838:26838:0215/010637.430909:29838738633:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7b0400002150 with delay 54000\n[26838:26838:0215/010637.432061:29838739784:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7b0400002150\n[ OK ] ThrottleTest.ThrottlingStorm (11 ms)\n[18/28] ThrottleTest.ThrottlingStorm (11 ms)\n[ RUN ] ProtocolHandlerTest.SendInitializeOnly\n[26839:26839:0215/010637.521403:29838829137:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002010 with delay 0\n[26839:26839:0215/010637.521796:29838829523:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002010\n[26839:26839:0215/010637.522145:29838829872: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[26839:26839:0215/010637.522251:29838829976:INFO:recurring-task.cc(55)] [Startup] Scheduling 7400 with a delay 500000, Now = 210919424\n[26839:26839:0215/010637.522331:29838830057:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f20 with delay 500\n[26839:26839:0215/010637.522416:29838830143:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f20\n[26839:26839:0215/010637.522838:29838830565: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[19/28] ProtocolHandlerTest.SendInitializeOnly (3 ms)\n[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly\n[26839:26839:0215/010637.524635:29838832365: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[20/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)\n[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes\n[26839:26839:0215/010637.525462:29838833191:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f00 with delay 0\n[26839:26839:0215/010637.525565:29838833295:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001cd0 with delay 0\n[26839:26839:0215/010637.525649:29838833372:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020d0 with delay 0\n[26839:26839:0215/010637.525740:29838833463:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002050 with delay 0\n[26839:26839:0215/010637.525810:29838833534:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b04000020e0 with delay 0\n[26839:26839:0215/010637.525884:29838833607:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002080 with delay 0\n[26839:26839:0215/010637.526357:29838834085:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001f00\n[26839:26839:0215/010637.526602:29838834328: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[26839:26839:0215/010637.526705:29838834432:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7112 with a delay 500000, Now = 210919424\n[26839:26839:0215/010637.526782:29838834508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001380 with delay 500\n[26839:26839:0215/010637.526861:29838834585:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400001cd0\n[26839:26839:0215/010637.526942:29838834665:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000020d0\n[26839:26839:0215/010637.527028:29838834751:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002050\n[26839:26839:0215/010637.527107:29838834830:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b04000020e0\n[26839:26839:0215/010637.527178:29838834902:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002080\n[26839:26839:0215/010637.527291:29838835015:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: \"oid0\" } }\n[26839:26839:0215/010637.527376:29838835102:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001380\n[26839:26839:0215/010637.527617:29838835343:INFO:protocol-handler.cc(352)] Sending token on client->server message: \"test token\"\n[26839:26839:0215/010637.528433:29838836159: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[21/28] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms)\n[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage\n[26839:26839:0215/010637.531242:29838838969: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[22/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.InvalidInboundMessage\n[26839:26839:0215/010637.532321:29838840051: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[26839:26839:0215/010637.532504:29838840231: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[26839:26839:0215/010637.532718:29838840444: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[26839:26839:0215/010637.532930:29838840657:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } }\n[ OK ] ProtocolHandlerTest.InvalidInboundMessage (2 ms)\n[23/28] ProtocolHandlerTest.InvalidInboundMessage (2 ms)\n[ RUN ] ProtocolHandlerTest.MajorVersionMismatch\n[26839:26839:0215/010637.533950:29838841677: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[26839:26839:0215/010637.534246:29838841973: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[24/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.MinorVersionMismatch\n[26839:26839:0215/010637.535217:29838842944: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[25/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms)\n[ RUN ] ProtocolHandlerTest.ConfigMessage\n[26839:26839:0215/010637.536197:29838843925: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[26839:26839:0215/010637.536339:29838844066:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400002130 with delay 0\n[26839:26839:0215/010637.536424:29838844150:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400002130\n[26839:26839:0215/010637.536604:29838844331: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[26839:26839:0215/010637.536703:29838844430:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7784 with a delay 500000, Now = 210919424\n[26839:26839:0215/010637.536783:29838844508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400001f60 with delay 500\n[26839:26839:0215/010637.536864:29838844589:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400001f60\n[26839:26839:0215/010637.536941:29838844666:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500\n[ OK ] ProtocolHandlerTest.ConfigMessage (17 ms)\n[26/28] ProtocolHandlerTest.ConfigMessage (17 ms)\n[ RUN ] ProtocolHandlerTest.ErrorMessage\n[26839:26839:0215/010637.553658:29838861387: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[27/28] ProtocolHandlerTest.ErrorMessage (1 ms)\n[ RUN ] ProtocolHandlerTest.TokenMismatch\n[26839:26839:0215/010637.554672:29838862402:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: \"test token\" registration_summary: { num_registrations: 0 registration_digest: \"\\3329\\243\\356^kK\\r2U\\277\\357\\225`\\030\\220\\257\\330\\007\\t\" } server_time_ms: 314159265 message_id: \"message-id-for-test\" } }\n[ OK ] ProtocolHandlerTest.TokenMismatch (0 ms)\n[28/28] ProtocolHandlerTest.TokenMismatch (0 ms)\nSUCCESS: all tests passed.\nTests took 0 seconds.\n", "outputs_ref": { "isolated": "5999877788875e6f2691882625654c6c22c66803", "isolatedserver": "https://isolateserver.appspot.com", "namespace": "default-gzip" }, "run_id": "430939cdb17a8711", "server_versions": [ "4105-f0295a3" ], "started_ts": "2019-02-15T09:06:32.553021", "state": "COMPLETED", "tags": [ "build_is_experimental:false", "buildername:Linux TSan Tests", "buildnumber:34207", "cpu:x86-64", "data:20cbf560bef95e4f588c61eea94982e4508f5d46", "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:f1de040c4595919a7f4ec4ebe49d4dadefb7e414", "user:None" ], "task_id": "430966ba3205fe10" } ] }