(view as text)
@@@STEP_CURSOR@cacheinvalidation_unittests on Mac-10.9@@@
@@@STEP_STARTED@@@
python -u /b/build/scripts/tools/runit.py python /b/build/scripts/slave/recipe_modules/swarming/resources/collect_gtest_task.py --swarming-client-dir /b/build/slave/Mac_ASan_64_Tests__1_/build/src/tools/swarming_client --temp-root-dir /tmp --merged-test-output /tmp/tmp_3a8O8.json -- collect --swarming https://chromium-swarm.appspot.com --decorate --print-status-updates --json /tmp/tmp8SngS7.json
in dir /b/build/slave/Mac_ASan_64_Tests__1_/build:
allow_subannotations: True
cmd: ['python', '-u', '/b/build/scripts/tools/runit.py', 'python', '/b/build/scripts/slave/recipe_modules/swarming/resources/collect_gtest_task.py', '--swarming-client-dir', '/b/build/slave/Mac_ASan_64_Tests__1_/build/src/tools/swarming_client', '--temp-root-dir', '/tmp', '--merged-test-output', '/tmp/tmp_3a8O8.json', '--', 'collect', '--swarming', 'https://chromium-swarm.appspot.com', '--decorate', '--print-status-updates', '--json', '/tmp/tmp8SngS7.json']
name: cacheinvalidation_unittests on Mac-10.9
step_test_data: <lambda>(...)
full environment:
AWS_CREDENTIAL_FILE: /b/build/site_config/.boto
BOTO_CONFIG: /b/build/site_config/.boto
BUILDBOT_BLAMELIST: [u'danakj@chromium.org', u'dpranke@chromium.org', u'mstensho@opera.com', u'spqchan@chromium.org', u'tedchoc@chromium.org', u'zmo@chromium.org']
BUILDBOT_BRANCH: master
BUILDBOT_BUILDBOTURL: http://build.chromium.org/p/chromium.memory/
BUILDBOT_BUILDERNAME: Mac ASan 64 Tests (1)
BUILDBOT_BUILDNUMBER: 16552
BUILDBOT_CLOBBER:
BUILDBOT_GOT_REVISION: None
BUILDBOT_MASTERNAME: chromium.memory
BUILDBOT_REVISION: ae057e0a986c713b8d3b619d1e0f4be61a3f963c
BUILDBOT_SCHEDULER: mac_asan_64_rel_trigger
BUILDBOT_SLAVENAME: vm689-m1
CHROME_HEADLESS: 1
GIT_USER_AGENT: darwin git/2.7.4 vm689-m1.golo.chromium.org
HOME: /Users/chrome-bot
LOGNAME: chrome-bot
PAGER: cat
PATH: /Users/chrome-bot/slavebin:/b/depot_tools:/usr/local/git/bin:/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/bin
PWD: /b/build/slave/Mac_ASan_64_Tests__1_/build
PYTHONPATH: /b/build/site_config:/b/build/scripts:/b/build/scripts/release:/b/build/third_party:/b/build/third_party/requests_1_2_3:/b/build_internal/site_config:/b/build_internal/symsrc:/b/build/slave:/b/build/third_party/buildbot_slave_8_4:/b/build/third_party/twisted_10_2:
SHELL: /bin/bash
SSH_AUTH_SOCK: /tmp/launch-EmMOc6/Listeners
USER: chrome-bot
+------------------------------------------------------------------------+
| Shard 0 https://chromium-swarm.appspot.com/user/task/2efe9532bed82a10 |
+------------------------------------------------------------------------+
IMPORTANT DEBUGGING NOTE: batches of tests are run inside their
own process. For debugging a test inside a debugger, use the
--gtest_filter=<your_test_name> flag along with
--single-process-tests.
Using sharding settings from environment. This is shard 0/1
Using 8 parallel jobs.
[ RUN ] ProtocolHandlerTest.SendInitializeOnly
[17864:3335:0524/193452:8701453784867:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000092d0 with delay 0
[17864:3335:0524/193452:8701454544834:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000092d0
[17864:3335:0524/193452:8701455103974: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 }
[17864:3335:0524/193452:8701455229488:INFO:recurring-task.cc(55)] [Startup] Scheduling 21929 with a delay 500000, Now = 210919424
[17864:3335:0524/193452:8701455275164:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009150 with delay 500
[17864:3335:0524/193452:8701455331657:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009150
[17864:3335:0524/193452:8701455653688: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 } }
[ OK ] ProtocolHandlerTest.SendInitializeOnly (4 ms)
[1/28] ProtocolHandlerTest.SendInitializeOnly (4 ms)
[ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly
[17864:3335:0524/193452:8701457406274: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" } }
[ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)
[2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms)
[ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes
[17864:3335:0524/193452:8701458002426:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008950 with delay 0
[17864:3335:0524/193452:8701458111214:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008930 with delay 0
[17864:3335:0524/193452:8701458180316:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008910 with delay 0
[17864:3335:0524/193452:8701458273718:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000088f0 with delay 0
[17864:3335:0524/193452:8701458359366:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000088d0 with delay 0
[17864:3335:0524/193452:8701458470408:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000088b0 with delay 0
[17864:3335:0524/193452:8701459294318:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008950
[17864:3335:0524/193452:8701459508762: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 }
[17864:3335:0524/193452:8701459570112:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10025 with a delay 500000, Now = 210919424
[17864:3335:0524/193452:8701459629848:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008730 with delay 500
[17864:3335:0524/193452:8701459694401:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008930
[17864:3335:0524/193452:8701459745937:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008910
[17864:3335:0524/193452:8701459799327:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000088f0
[17864:3335:0524/193452:8701459857315:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000088d0
[17864:3335:0524/193452:8701459903140:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000088b0
[17864:3335:0524/193452:8701459961866:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } }
[17864:3335:0524/193452:8701460042696:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008730
[17864:3335:0524/193452:8701460286315:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token"
[17864:3335:0524/193452:8701460724818: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 } }
[ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms)
[3/28] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms)
[ RUN ] ProtocolHandlerTest.IncomingCompositeMessage
[17864:3335:0524/193452:8701464124605: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 } }
[ OK ] ProtocolHandlerTest.IncomingCompositeMessage (2 ms)
[4/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms)
[ RUN ] ProtocolHandlerTest.InvalidInboundMessage
[17864:3335:0524/193452:8701464924752: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 } }
[17864:3335:0524/193452:8701465039187: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" }
[17864:3335:0524/193452:8701465146000: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 } }
[17864:3335:0524/193452:8701465262452: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 } }
[ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms)
[5/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms)
[ RUN ] ProtocolHandlerTest.MajorVersionMismatch
[17864:3335:0524/193452:8701465816088: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 } }
[17864:3335:0524/193452:8701465942164: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 } }
[ OK ] ProtocolHandlerTest.MajorVersionMismatch (0 ms)
[6/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms)
[ RUN ] ProtocolHandlerTest.MinorVersionMismatch
[17864:3335:0524/193452:8701466481579: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" } }
[ OK ] ProtocolHandlerTest.MinorVersionMismatch (0 ms)
[7/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms)
[ RUN ] ProtocolHandlerTest.ConfigMessage
[17864:3335:0524/193452:8701467077414: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" } }
[17864:3335:0524/193452:8701467214380:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073f0 with delay 0
[17864:3335:0524/193452:8701467256925:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000073f0
[17864:3335:0524/193452:8701467341494: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 }
[17864:3335:0524/193452:8701467387217:INFO:recurring-task.cc(55)] [Send-info] Scheduling 93353 with a delay 500000, Now = 210919424
[17864:3335:0524/193452:8701467445354:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073d0 with delay 500
[17864:3335:0524/193452:8701467497446:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000073d0
[17864:3335:0524/193452:8701467541501:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500
[ OK ] ProtocolHandlerTest.ConfigMessage (7 ms)
[8/28] ProtocolHandlerTest.ConfigMessage (7 ms)
[ RUN ] ProtocolHandlerTest.ErrorMessage
[17864:3335:0524/193452:8701474053587: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" } }
[ OK ] ProtocolHandlerTest.ErrorMessage (1 ms)
[9/28] ProtocolHandlerTest.ErrorMessage (1 ms)
[ RUN ] ProtocolHandlerTest.TokenMismatch
[17864:3335:0524/193452:8701474625664: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" } }
[ OK ] ProtocolHandlerTest.TokenMismatch (0 ms)
[10/28] ProtocolHandlerTest.TokenMismatch (0 ms)
[ RUN ] InvalidationClientImplTest.Start
[17863:3335:0524/193452:8701410009427:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000090f0 with delay 0
[17863:3335:0524/193452:8701410966728:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701411505091:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008c50 with delay 0
[17863:3335:0524/193452:8701411589584:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000090f0
[17863:3335:0524/193452:8701411670678:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008c50
[17863:3335:0524/193452:8701411810494:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701412010709:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008bf0 with delay 0
[17863:3335:0524/193452:8701412093487:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008bf0
[17863:3335:0524/193452:8701412159429:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701412233774:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008bb0 with delay 0
[17863:3335:0524/193452:8701412304174:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008bb0
[17863:3335:0524/193452:8701412421786:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701412507932:INFO:recurring-task.cc(55)] [Startup] Scheduling 22057 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701412591548:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008b90 with delay 0
[17863:3335:0524/193452:8701412766172:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008b90
[17863:3335:0524/193452:8701412921652:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3283933590348389712" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701413021496:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 21801 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701413106729:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008b50 with delay 500
[17863:3335:0524/193452:8701413194287:INFO:recurring-task.cc(55)] [Retry] Scheduling 22057 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701413280544:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008b30 with delay 60000
[17863:3335:0524/193452:8701413363585:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008b50
[17863:3335:0524/193452:8701413446747:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701413571586:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701413874222: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: "3283933590348389712" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701414281094:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008af0 with delay 0
[17863:3335:0524/193452:8701414351091:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008af0
[17863:3335:0524/193452:8701414650298:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3283933590348389712" 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" } }
[17863:3335:0524/193452:8701414827367:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3283933590348389712"
[17863:3335:0524/193452:8701414903055:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701415024792:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 18025 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701415094491:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008ad0 with delay 1200000
[17863:3335:0524/193452:8701415196486:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701415508987:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701415591605:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 119305 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701415662716:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000089f0 with delay 0
[17863:3335:0524/193452:8701415793712: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
[17863:3335:0524/193452:8701415908138:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000089f0
[17863:3335:0524/193452:8701416107804:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008990 with delay 0
[17863:3335:0524/193452:8701416205565:INFO:recurring-task.cc(55)] [Retry] Scheduling 119305 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701416291257:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008950 with delay 10000
[17863:3335:0524/193452:8701416362804:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008990
[17863:3335:0524/193452:8701416434067:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[ OK ] InvalidationClientImplTest.Start (8 ms)
[11/28] InvalidationClientImplTest.Start (8 ms)
[ RUN ] InvalidationClientImplTest.GenerateNonce
[17863:3335:0524/193452:8701417735354:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008370 with delay 0
[17863:3335:0524/193452:8701417835811:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[ OK ] InvalidationClientImplTest.GenerateNonce (1 ms)
[12/28] InvalidationClientImplTest.GenerateNonce (1 ms)
[ RUN ] InvalidationClientImplTest.Register
[17863:3335:0524/193452:8701418771934:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007d50 with delay 0
[17863:3335:0524/193452:8701418924350:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701419436907:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000077b0 with delay 0
[17863:3335:0524/193452:8701419507674:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007d50
[17863:3335:0524/193452:8701419594376:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000077b0
[17863:3335:0524/193452:8701419746888:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701419868309:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007750 with delay 0
[17863:3335:0524/193452:8701419954331:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007750
[17863:3335:0524/193452:8701420013502:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701420084542:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007710 with delay 0
[17863:3335:0524/193452:8701420178172:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007710
[17863:3335:0524/193452:8701420258225:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701420350488:INFO:recurring-task.cc(55)] [Startup] Scheduling 1577 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701420425589:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000076f0 with delay 0
[17863:3335:0524/193452:8701420491666:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000076f0
[17863:3335:0524/193452:8701420649877:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7921192932074441671" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701420740176:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1321 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701420819089:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000076d0 with delay 500
[17863:3335:0524/193452:8701420887837:INFO:recurring-task.cc(55)] [Retry] Scheduling 1577 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701420962628:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000076b0 with delay 60000
[17863:3335:0524/193452:8701421045416:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000076d0
[17863:3335:0524/193452:8701421118935:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701421210712:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701421439845: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: "7921192932074441671" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701421710132:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007670 with delay 0
[17863:3335:0524/193452:8701421787448:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007670
[17863:3335:0524/193452:8701422016750:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7921192932074441671" 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" } }
[17863:3335:0524/193452:8701422175011:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7921192932074441671"
[17863:3335:0524/193452:8701422250862:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701422333047:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15209 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701422438828:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007650 with delay 1200000
[17863:3335:0524/193452:8701422521867:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701422765828:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701422844850:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 116617 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701422916446:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007570 with delay 0
[17863:3335:0524/193452:8701423015137: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
[17863:3335:0524/193452:8701423124298:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007570
[17863:3335:0524/193452:8701423273931:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007510 with delay 0
[17863:3335:0524/193452:8701423357910:INFO:recurring-task.cc(55)] [Retry] Scheduling 116617 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701423421794:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000074d0 with delay 10000
[17863:3335:0524/193452:8701423487947:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007510
[17863:3335:0524/193452:8701423550517:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701423755814:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000074b0 with delay 0
[17863:3335:0524/193452:8701423834431:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000074b0
[17863:3335:0524/193452:8701423954171:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1
[17863:3335:0524/193452:8701424055389:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1
[17863:3335:0524/193452:8701424141091:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1
[17863:3335:0524/193452:8701424303796:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1321 with a delay 500000, Now = 211469424
[17863:3335:0524/193452:8701424390068:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007490 with delay 500
[17863:3335:0524/193452:8701424463824:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1449 with a delay 60000000, Now = 211469424
[17863:3335:0524/193452:8701424531810:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007470 with delay 60000
[17863:3335:0524/193452:8701424628256:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007490
[17863:3335:0524/193452:8701424700712:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701424813845:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701424880270:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token"
[17863:3335:0524/193452:8701425201167: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 } } }
[17863:3335:0524/193452:8701425422951:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701425701972:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000007430 with delay 0
[17863:3335:0524/193452:8701425804318:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007430
[17863:3335:0524/193452:8701426329112: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 } } } }
[17863:3335:0524/193452:8701426610046: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
[17863:3335:0524/193452:8701426810464:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } }
[17863:3335:0524/193452:8701427046167:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } }
[17863:3335:0524/193452:8701427244074:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } }
[17863:3335:0524/193452:8701427631225:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000074d0
[ OK ] InvalidationClientImplTest.Register (10 ms)
[13/28] InvalidationClientImplTest.Register (10 ms)
[ RUN ] InvalidationClientImplTest.Invalidations
[17863:3335:0524/193452:8701429683757:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006d10 with delay 0
[17863:3335:0524/193452:8701429793496:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701430484098:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006750 with delay 0
[17863:3335:0524/193452:8701430582817:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006d10
[17863:3335:0524/193452:8701430658029:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006750
[17863:3335:0524/193452:8701430790148:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701430908675:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066f0 with delay 0
[17863:3335:0524/193452:8701430998882:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000066f0
[17863:3335:0524/193452:8701431060884:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701431139084:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066b0 with delay 0
[17863:3335:0524/193452:8701431216948:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000066b0
[17863:3335:0524/193452:8701431283157:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701431409007:INFO:recurring-task.cc(55)] [Startup] Scheduling 90153 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701431492234:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006690 with delay 0
[17863:3335:0524/193452:8701431562171:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006690
[17863:3335:0524/193452:8701431731595:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2836622492317250605" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701431817525:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 89897 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701431896677:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006670 with delay 500
[17863:3335:0524/193452:8701431975649:INFO:recurring-task.cc(55)] [Retry] Scheduling 90153 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701432047486:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006650 with delay 60000
[17863:3335:0524/193452:8701432123178:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006670
[17863:3335:0524/193452:8701432217056:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701432326972:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701432535586: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: "-2836622492317250605" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701432726029:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006610 with delay 0
[17863:3335:0524/193452:8701432781534:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006610
[17863:3335:0524/193452:8701432937091:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2836622492317250605" 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" } }
[17863:3335:0524/193452:8701433044812:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2836622492317250605"
[17863:3335:0524/193452:8701433143528:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701433231414:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 8697 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701433322867:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000065f0 with delay 1200000
[17863:3335:0524/193452:8701433413247:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701433645384:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701433694666:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 111241 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701433729442:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006510 with delay 0
[17863:3335:0524/193452:8701433798728: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
[17863:3335:0524/193452:8701433914671:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006510
[17863:3335:0524/193452:8701434086929:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000064b0 with delay 0
[17863:3335:0524/193452:8701434205385:INFO:recurring-task.cc(55)] [Retry] Scheduling 111241 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701434278715:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006470 with delay 10000
[17863:3335:0524/193452:8701434347864:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000064b0
[17863:3335:0524/193452:8701434412948:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701434518536:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701434663758:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006450 with delay 0
[17863:3335:0524/193452:8701434747117:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006450
[17863:3335:0524/193452:8701435102686: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 } } }
[17863:3335:0524/193452:8701435321657: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
[17863:3335:0524/193452:8701435463690: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" }
[17863:3335:0524/193452:8701435719904:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true }
[17863:3335:0524/193452:8701435924844:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true }
[17863:3335:0524/193452:8701436146091:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006310 with delay 0
[17863:3335:0524/193452:8701436225494:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x6020000062f0 with delay 0
[17863:3335:0524/193452:8701436309544:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x6020000062d0 with delay 0
[17863:3335:0524/193452:8701436385270:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006310
[17863:3335:0524/193452:8701436519052:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 89897 with a delay 500000, Now = 211519424
[17863:3335:0524/193452:8701436600391:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x6020000062b0 with delay 500
[17863:3335:0524/193452:8701436676485:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x6020000062f0
[17863:3335:0524/193452:8701436761064:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x6020000062d0
[17863:3335:0524/193452:8701436858476:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x6020000062b0
[17863:3335:0524/193452:8701436934674:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701437050744:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701437133851:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token"
[17863:3335:0524/193452:8701437475427: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 } } }
[ OK ] InvalidationClientImplTest.Invalidations (10 ms)
[14/28] InvalidationClientImplTest.Invalidations (10 ms)
[ RUN ] InvalidationClientImplTest.ServerRequests
[17863:3335:0524/193452:8701438923290:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005cb0 with delay 0
[17863:3335:0524/193452:8701439037057:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701439434489:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005810 with delay 0
[17863:3335:0524/193452:8701439515164:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005cb0
[17863:3335:0524/193452:8701439600267:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005810
[17863:3335:0524/193452:8701439730994:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701439848751:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000057b0 with delay 0
[17863:3335:0524/193452:8701439935362:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000057b0
[17863:3335:0524/193452:8701440000874:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701440074952:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005770 with delay 0
[17863:3335:0524/193452:8701440159766:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005770
[17863:3335:0524/193452:8701440226496:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701440319578:INFO:recurring-task.cc(55)] [Startup] Scheduling 66473 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701440394652:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005750 with delay 0
[17863:3335:0524/193452:8701440460044:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005750
[17863:3335:0524/193452:8701440597394:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3994168448696752354" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701440687254:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 66217 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701440773887:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005730 with delay 500
[17863:3335:0524/193452:8701440845106:INFO:recurring-task.cc(55)] [Retry] Scheduling 66473 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701440911347:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005710 with delay 60000
[17863:3335:0524/193452:8701440989744:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005730
[17863:3335:0524/193452:8701441052755:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701441151328:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701441384687: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: "-3994168448696752354" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701441650805:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000056d0 with delay 0
[17863:3335:0524/193452:8701441741085:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000056d0
[17863:3335:0524/193452:8701441953289:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3994168448696752354" 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" } }
[17863:3335:0524/193452:8701442122791:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3994168448696752354"
[17863:3335:0524/193452:8701442190249:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701442274608:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 3241 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701442341546:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000056b0 with delay 1200000
[17863:3335:0524/193452:8701442414865:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701442662017:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701442755964:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 106633 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701442819645:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000055d0 with delay 0
[17863:3335:0524/193452:8701442967498: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
[17863:3335:0524/193452:8701443062974:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000055d0
[17863:3335:0524/193452:8701443206770:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005570 with delay 0
[17863:3335:0524/193452:8701443292150:INFO:recurring-task.cc(55)] [Retry] Scheduling 106633 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701443367049:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005530 with delay 10000
[17863:3335:0524/193452:8701443433526:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005570
[17863:3335:0524/193452:8701443498817:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701443610488:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701443725836:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000005510 with delay 0
[17863:3335:0524/193452:8701443792671:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000005510
[17863:3335:0524/193452:8701444045856: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 } }
[17863:3335:0524/193452:8701444209030: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
[17863:3335:0524/193452:8701444298592:INFO:protocol-handler.cc(294)] Adding subtree: { }
[17863:3335:0524/193452:8701444379751:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 66217 with a delay 500000, Now = 211469424
[17863:3335:0524/193452:8701444464968:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000054f0 with delay 500
[17863:3335:0524/193452:8701444542192:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false
[17863:3335:0524/193452:8701445023170: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 }
[17863:3335:0524/193452:8701445167824:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x6020000054f0
[17863:3335:0524/193452:8701445235382:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701445403996:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701445470177:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token"
[17863:3335:0524/193452:8701446015002: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 } }
[17863:3335:0524/193452:8701446352490:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000005530
[ OK ] InvalidationClientImplTest.ServerRequests (8 ms)
[15/28] InvalidationClientImplTest.ServerRequests (8 ms)
[ RUN ] InvalidationClientImplTest.IncomingErrorMessage
[17863:3335:0524/193452:8701447546169:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004ef0 with delay 0
[17863:3335:0524/193452:8701447666592:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701448046907:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000049b0 with delay 0
[17863:3335:0524/193452:8701448121237:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004ef0
[17863:3335:0524/193452:8701448240154:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000049b0
[17863:3335:0524/193452:8701448361149:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701448494847:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004950 with delay 0
[17863:3335:0524/193452:8701448578598:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004950
[17863:3335:0524/193452:8701448652305:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701448725454:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004910 with delay 0
[17863:3335:0524/193452:8701448793298:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004910
[17863:3335:0524/193452:8701448847706:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701448931158:INFO:recurring-task.cc(55)] [Startup] Scheduling 174889 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701449018458:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000048f0 with delay 0
[17863:3335:0524/193452:8701449090412:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000048f0
[17863:3335:0524/193452:8701449209564:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4233170673677885152" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701449318850:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 174633 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701449392705:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000048d0 with delay 500
[17863:3335:0524/193452:8701449461174:INFO:recurring-task.cc(55)] [Retry] Scheduling 174889 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701449555258:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000048b0 with delay 60000
[17863:3335:0524/193452:8701449644150:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000048d0
[17863:3335:0524/193452:8701449730071:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701449844436:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701450086845: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: "-4233170673677885152" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701450311434:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004870 with delay 0
[17863:3335:0524/193452:8701450385788:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004870
[17863:3335:0524/193452:8701450656377:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4233170673677885152" 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" } }
[17863:3335:0524/193452:8701450794765:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4233170673677885152"
[17863:3335:0524/193452:8701450886615:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701450978702:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 111129 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701451074725:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004850 with delay 1200000
[17863:3335:0524/193452:8701451146315:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701451334926:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701451434527:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 102409 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701451501116:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004770 with delay 0
[17863:3335:0524/193452:8701451609945: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
[17863:3335:0524/193452:8701451724171:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004770
[17863:3335:0524/193452:8701451908765:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004710 with delay 0
[17863:3335:0524/193452:8701451996828:INFO:recurring-task.cc(55)] [Retry] Scheduling 102409 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701452076695:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000046d0 with delay 10000
[17863:3335:0524/193452:8701452154389:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004710
[17863:3335:0524/193452:8701452242990:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701452336972:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701452480226:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000046b0 with delay 0
[17863:3335:0524/193452:8701452547447:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000046b0
[17863:3335:0524/193452:8701452759634: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" } }
[17863:3335:0524/193452:8701452910695: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
[17863:3335:0524/193452:8701453006375:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message
[17863:3335:0524/193452:8701453257904:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000046d0
[ OK ] InvalidationClientImplTest.IncomingErrorMessage (6 ms)
[16/28] InvalidationClientImplTest.IncomingErrorMessage (6 ms)
[ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage
[17863:3335:0524/193452:8701454605866:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004070 with delay 0
[17863:3335:0524/193452:8701454706010:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701455307730:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003a70 with delay 0
[17863:3335:0524/193452:8701455378791:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004070
[17863:3335:0524/193452:8701455443668:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003a70
[17863:3335:0524/193452:8701455555316:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701455675282:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003a10 with delay 0
[17863:3335:0524/193452:8701455758984:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003a10
[17863:3335:0524/193452:8701455827850:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701455900215:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000039d0 with delay 0
[17863:3335:0524/193452:8701455973378:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000039d0
[17863:3335:0524/193452:8701456036849:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701456108995:INFO:recurring-task.cc(55)] [Startup] Scheduling 156713 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701456199762:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000039b0 with delay 0
[17863:3335:0524/193452:8701456278917:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000039b0
[17863:3335:0524/193452:8701456407052:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3717707908992086642" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701456496336:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 156457 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701456566429:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003990 with delay 500
[17863:3335:0524/193452:8701456635118:INFO:recurring-task.cc(55)] [Retry] Scheduling 156713 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701456693054:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003970 with delay 60000
[17863:3335:0524/193452:8701456761818:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003990
[17863:3335:0524/193452:8701456838868:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701456929407:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701457151864: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: "3717707908992086642" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701457370652:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003930 with delay 0
[17863:3335:0524/193452:8701457483422:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003930
[17863:3335:0524/193452:8701457714214:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3717707908992086642" 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" } }
[17863:3335:0524/193452:8701457826270:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3717707908992086642"
[17863:3335:0524/193452:8701457904089:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701457990467:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 107609 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701458065404:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003910 with delay 1200000
[17863:3335:0524/193452:8701458139767:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701458383850:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701458482767:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 99529 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701458553022:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003830 with delay 0
[17863:3335:0524/193452:8701458636342: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
[17863:3335:0524/193452:8701458710128:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003830
[17863:3335:0524/193452:8701458833416:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000037d0 with delay 0
[17863:3335:0524/193452:8701458898954:INFO:recurring-task.cc(55)] [Retry] Scheduling 99529 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701458953670:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003790 with delay 10000
[17863:3335:0524/193452:8701459030956:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000037d0
[17863:3335:0524/193452:8701459079226:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701459161364:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003770 with delay 0
[17863:3335:0524/193452:8701459226336:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000003770
[17863:3335:0524/193452:8701459296466:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1
[17863:3335:0524/193452:8701459408326:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 156457 with a delay 500000, Now = 211469424
[17863:3335:0524/193452:8701459471692:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003750 with delay 500
[17863:3335:0524/193452:8701459551969:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 156585 with a delay 60000000, Now = 211469424
[17863:3335:0524/193452:8701459604185:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003730 with delay 60000
[17863:3335:0524/193452:8701459693529:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000003750
[17863:3335:0524/193452:8701459756077:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701459838512:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701459889258:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token"
[17863:3335:0524/193452:8701460090216: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 } } }
[17863:3335:0524/193452:8701460242395:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701460321477:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x6020000036f0 with delay 0
[17863:3335:0524/193452:8701460372026:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x6020000036f0
[17863:3335:0524/193452:8701460560030: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" } }
[17863:3335:0524/193452:8701460698054: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
[17863:3335:0524/193452:8701460760458:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message
[17863:3335:0524/193452:8701460907244:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects
[17863:3335:0524/193452:8701461123431:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000003790
[ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (8 ms)
[17/28] InvalidationClientImplTest.IncomingAuthErrorMessage (8 ms)
[ RUN ] InvalidationClientImplTest.NetworkTimeouts
[17863:3335:0524/193452:8701462540466:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003050 with delay 0
[17863:3335:0524/193452:8701462626408:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701463024606:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002bb0 with delay 0
[17863:3335:0524/193452:8701463088451:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003050
[17863:3335:0524/193452:8701463145688:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002bb0
[17863:3335:0524/193452:8701463268610:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701463350035:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b50 with delay 0
[17863:3335:0524/193452:8701463417472:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b50
[17863:3335:0524/193452:8701463471247:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701463536107:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b10 with delay 0
[17863:3335:0524/193452:8701463593674:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b10
[17863:3335:0524/193452:8701463648432:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701463731305:INFO:recurring-task.cc(55)] [Startup] Scheduling 133673 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701463800154:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002af0 with delay 0
[17863:3335:0524/193452:8701463860305:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002af0
[17863:3335:0524/193452:8701463980982:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1968020370692848649" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701464039669:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 133417 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701464094251:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ad0 with delay 500
[17863:3335:0524/193452:8701464152768:INFO:recurring-task.cc(55)] [Retry] Scheduling 133673 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701464203268:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ab0 with delay 60000
[17863:3335:0524/193452:8701464260887:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002ad0
[17863:3335:0524/193452:8701464323287:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701464399475:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701464587536: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: "1968020370692848649" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701464795917:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a70 with delay 0
[17863:3335:0524/193452:8701464849691:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002a70
[17863:3335:0524/193452:8701465031485:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1968020370692848649" 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" } }
[17863:3335:0524/193452:8701465131807:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1968020370692848649"
[17863:3335:0524/193452:8701465189292:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701465254747:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 102857 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701465340026:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a50 with delay 1200000
[17863:3335:0524/193452:8701465412846:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701465600306:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701465672806:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 95497 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701465739028:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002970 with delay 0
[17863:3335:0524/193452:8701465817837: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
[17863:3335:0524/193452:8701465888114:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002970
[17863:3335:0524/193452:8701466015544:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002910 with delay 0
[17863:3335:0524/193452:8701466086010:INFO:recurring-task.cc(55)] [Retry] Scheduling 95497 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701466142162:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000028d0 with delay 10000
[17863:3335:0524/193452:8701466190894:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002910
[17863:3335:0524/193452:8701466235346:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701466315797:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000028b0 with delay 0
[17863:3335:0524/193452:8701466370364:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000028b0
[17863:3335:0524/193452:8701466435891:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1
[17863:3335:0524/193452:8701466529637:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 133417 with a delay 500000, Now = 211469424
[17863:3335:0524/193452:8701466586644:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000002890 with delay 500
[17863:3335:0524/193452:8701466648998:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 133545 with a delay 60000000, Now = 211469424
[17863:3335:0524/193452:8701466700212:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000002870 with delay 60000
[17863:3335:0524/193452:8701466799908:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000002890
[17863:3335:0524/193452:8701466877067:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701466963776:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701467016414:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token"
[17863:3335:0524/193452:8701467208814: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 } } }
[17863:3335:0524/193452:8701467425554:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000028d0
[17863:3335:0524/193452:8701467813024:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x602000002ab0
[17863:3335:0524/193452:8701467867071:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x602000002870
[17863:3335:0524/193452:8701467946047: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
[17863:3335:0524/193452:8701468020766:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true
[17863:3335:0524/193452:8701468136066: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 }
[17863:3335:0524/193452:8701468196109:INFO:recurring-task.cc(55)] [Send-info] Scheduling 133417 with a delay 500000, Now = 271469424
[17863:3335:0524/193452:8701468256657:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000002830 with delay 500
[17863:3335:0524/193452:8701468315008:INFO:recurring-task.cc(55)] [Retry] Scheduling 133545 with a delay 60000000, Now = 271469424
[17863:3335:0524/193452:8701468367692:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x602000002810 with delay 60000
[17863:3335:0524/193452:8701468535986:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x602000002830
[17863:3335:0524/193452:8701468646050:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701468747964:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701468811527:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token"
[17863:3335:0524/193452:8701469046546: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 } }
[ OK ] InvalidationClientImplTest.NetworkTimeouts (8 ms)
[18/28] InvalidationClientImplTest.NetworkTimeouts (8 ms)
[ RUN ] InvalidationClientImplTest.NoRegistrationSummary
[17863:3335:0524/193452:8701470639814:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002210 with delay 0
[17863:3335:0524/193452:8701470730624:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701471081747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d70 with delay 0
[17863:3335:0524/193452:8701471155631:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002210
[17863:3335:0524/193452:8701471224332:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001d70
[17863:3335:0524/193452:8701471318254:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701471414095:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d10 with delay 0
[17863:3335:0524/193452:8701471482322:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001d10
[17863:3335:0524/193452:8701471535588:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701471598190:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cd0 with delay 0
[17863:3335:0524/193452:8701471661417:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cd0
[17863:3335:0524/193452:8701471713458:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701471779036:INFO:recurring-task.cc(55)] [Startup] Scheduling 242089 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701471848736:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cb0 with delay 0
[17863:3335:0524/193452:8701471944262:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cb0
[17863:3335:0524/193452:8701472056172:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-242297162713950966" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701472154194:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 241833 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701472232730:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001c90 with delay 500
[17863:3335:0524/193452:8701472297852:INFO:recurring-task.cc(55)] [Retry] Scheduling 242089 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701472358806:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001c70 with delay 60000
[17863:3335:0524/193452:8701472416956:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001c90
[17863:3335:0524/193452:8701472479276:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701472593447:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701472806609: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: "-242297162713950966" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701473008802:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001c30 with delay 0
[17863:3335:0524/193452:8701473069317:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001c30
[17863:3335:0524/193452:8701473263387:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-242297162713950966" 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" } }
[17863:3335:0524/193452:8701473403098:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-242297162713950966"
[17863:3335:0524/193452:8701473469389:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701473549614:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 98281 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701473608047:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001c10 with delay 1200000
[17863:3335:0524/193452:8701473674509:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701473867034:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701473937882:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 90505 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701474006428:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001b30 with delay 0
[17863:3335:0524/193452:8701474099456: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
[17863:3335:0524/193452:8701474188707:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001b30
[17863:3335:0524/193452:8701474316116:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001ad0 with delay 0
[17863:3335:0524/193452:8701474407550:INFO:recurring-task.cc(55)] [Retry] Scheduling 90505 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701474481912:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001a90 with delay 10000
[17863:3335:0524/193452:8701474569125:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001ad0
[17863:3335:0524/193452:8701474636926:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701474767042:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701474839536:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000001a70 with delay 0
[17863:3335:0524/193452:8701474911230:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000001a70
[17863:3335:0524/193452:8701475038634: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" } }
[17863:3335:0524/193452:8701475200166:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000001a90
[17863:3335:0524/193452:8701475631750: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" } }
[ OK ] InvalidationClientImplTest.NoRegistrationSummary (6 ms)
[19/28] InvalidationClientImplTest.NoRegistrationSummary (6 ms)
[ RUN ] InvalidationClientImplTest.Heartbeats
[17863:3335:0524/193452:8701476611145:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001490 with delay 0
[17863:3335:0524/193452:8701476699757:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1>
[17863:3335:0524/193452:8701477051424:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000ff0 with delay 0
[17863:3335:0524/193452:8701477111577:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001490
[17863:3335:0524/193452:8701477176454:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000ff0
[17863:3335:0524/193452:8701477274331:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } }
[17863:3335:0524/193452:8701477404846:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000f90 with delay 0
[17863:3335:0524/193452:8701477485936:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000f90
[17863:3335:0524/193452:8701477553071:WARNING:invalidation-client-core.cc(961)] Could not read state blob:
[17863:3335:0524/193452:8701477610796:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000f50 with delay 0
[17863:3335:0524/193452:8701477674764:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000f50
[17863:3335:0524/193452:8701477728050:INFO:invalidation-client-core.cc(351)] Starting with no previous state
[17863:3335:0524/193452:8701477796827:INFO:recurring-task.cc(55)] [Startup] Scheduling 224809 with a delay 0, Now = 210919424
[17863:3335:0524/193452:8701477862250:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000f30 with delay 0
[17863:3335:0524/193452:8701477921845:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000f30
[17863:3335:0524/193452:8701478041790:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4330187441712543682" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED }
[17863:3335:0524/193452:8701478150512:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 224553 with a delay 500000, Now = 210919424
[17863:3335:0524/193452:8701478216196:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000f10 with delay 500
[17863:3335:0524/193452:8701478295555:INFO:recurring-task.cc(55)] [Retry] Scheduling 224809 with a delay 60000000, Now = 210919424
[17863:3335:0524/193452:8701478363782:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000ef0 with delay 60000
[17863:3335:0524/193452:8701478453548:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000000f10
[17863:3335:0524/193452:8701478520378:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701478606304:INFO:invalidation-client-core.cc(488)] Return client token = ""
[17863:3335:0524/193452:8701478793470: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: "-4330187441712543682" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } }
[17863:3335:0524/193452:8701478984117:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000000eb0 with delay 0
[17863:3335:0524/193452:8701479051797:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000000eb0
[17863:3335:0524/193452:8701479237805:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4330187441712543682" 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" } }
[17863:3335:0524/193452:8701479385978:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4330187441712543682"
[17863:3335:0524/193452:8701479439486:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = ""
[17863:3335:0524/193452:8701479501585:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 95289 with a delay 1200000000, Now = 211419424
[17863:3335:0524/193452:8701479577745:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000000e90 with delay 1200000
[17863:3335:0524/193452:8701479631657:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready
[17863:3335:0524/193452:8701479825752:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701479881726:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 87625 with a delay 0, Now = 211419424
[17863:3335:0524/193452:8701479934385:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000000db0 with delay 0
[17863:3335:0524/193452:8701480012886: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
[17863:3335:0524/193452:8701480086288:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000000db0
[17863:3335:0524/193452:8701480197406:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000000d50 with delay 0
[17863:3335:0524/193452:8701480277957:INFO:recurring-task.cc(55)] [Retry] Scheduling 87625 with a delay 10000000, Now = 211419424
[17863:3335:0524/193452:8701480331396:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000000d10 with delay 10000
[17863:3335:0524/193452:8701480388567:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000000d50
[17863:3335:0524/193452:8701480436567:INFO:invalidation-client-core.cc(146)] Write state completed: 1,
[17863:3335:0524/193452:8701480581038:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000000d10
[17863:3335:0524/193452:8701480971798:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x602000000ef0
[17863:3335:0524/193452:8701488241568:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x602000000e90
[17863:3335:0524/193452:8701488353324:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701488437567:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2>
[17863:3335:0524/193452:8701488499572:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false
[17863:3335:0524/193452:8701488775454: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 }
[17863:3335:0524/193452:8701488859465:INFO:recurring-task.cc(55)] [Send-info] Scheduling 224553 with a delay 500000, Now = 1411419424
[17863:3335:0524/193452:8701488918042:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000000cf0 with delay 500
[17863:3335:0524/193452:8701488976286:INFO:recurring-task.cc(55)] [Retry] Scheduling 95289 with a delay 1200000000, Now = 1411419424
[17863:3335:0524/193452:8701489031028:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x602000000cd0 with delay 1200000
[17863:3335:0524/193452:8701489096217:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x602000000cf0
[17863:3335:0524/193452:8701489146945:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701489295590:INFO:invalidation-client-core.cc(488)] Return client token = "new token"
[17863:3335:0524/193452:8701489401035:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token"
[17863:3335:0524/193452:8701489734612: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 } }
[ OK ] InvalidationClientImplTest.Heartbeats (15 ms)
[20/28] InvalidationClientImplTest.Heartbeats (15 ms)
[ RUN ] ProtocolHandlerTest.TokenMissing
[17865:3335:0524/193452:8701588598954:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000092d0 with delay 0
[17865:3335:0524/193452:8701588684968:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000092d0
[17865:3335:0524/193452:8701589274004: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 }
[17865:3335:0524/193452:8701589385131:INFO:recurring-task.cc(55)] [Send-info] Scheduling 21929 with a delay 500000, Now = 210919424
[17865:3335:0524/193452:8701589446430:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000092b0 with delay 500
[17865:3335:0524/193452:8701589501917:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000092b0
[17865:3335:0524/193452:8701589600382:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { }
[17865:3335:0524/193452:8701589697172:WARNING:protocol-handler.cc(313)] Unable to build message
[ OK ] ProtocolHandlerTest.TokenMissing (2 ms)
[21/28] ProtocolHandlerTest.TokenMissing (2 ms)
[ RUN ] ProtocolHandlerTest.InvalidOutboundMessage
[17865:3335:0524/193452:8701590368525:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008ed0 with delay 0
[17865:3335:0524/193452:8701590429836:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008ed0
[17865:3335:0524/193452:8701590500866:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 17193 with a delay 500000, Now = 210919424
[17865:3335:0524/193452:8701590550637:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008eb0 with delay 500
[17865:3335:0524/193452:8701590610307:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008eb0
[17865:3335:0524/193452:8701590871414:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token"
[17865:3335:0524/193452:8701591049709: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 }
[17865:3335:0524/193452:8701591177677: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 } }
[17865:3335:0524/193452:8701591342208: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 } } }
[17865:3335:0524/193452:8701591516024: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 } } }
[ OK ] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)
[22/28] ProtocolHandlerTest.InvalidOutboundMessage (2 ms)
[ RUN ] ProtocolHandlerTest.UnparseableInboundMessage
[17865:3335:0524/193452:8701592112216:INFO:protocol-handler.cc(139)] Incoming message: { }
[17865:3335:0524/193452:8701592168705:ERROR:ticl-message-validator.cc(361)] required field header missing from { }
[17865:3335:0524/193452:8701592281706:ERROR:protocol-handler.cc(145)] Received invalid message: { }
[ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)
[23/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms)
[ RUN ] RecurringTaskTest.PeriodicTask
[17865:3335:0524/193452:8701592588647:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 234952809 with a delay 10000, Now = 0
[17865:3335:0524/193452:8701592633934:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000008a50 with delay 10
[17865:3335:0524/193452:8701592680150:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000008a50
[17865:3335:0524/193452:8701592749462:INFO:recurring-task_test.cc(71)] (10000) Task running: 1
[17865:3335:0524/193452:8701592795342:INFO:recurring-task.cc(55)] [Retry] Scheduling 234952809 with a delay 60000, Now = 10000
[17865:3335:0524/193452:8701592850431:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000008a30 with delay 60
[17865:3335:0524/193452:8701592900429:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000008a30
[17865:3335:0524/193452:8701592943618:INFO:recurring-task_test.cc(71)] (70000) Task running: 2
[17865:3335:0524/193452:8701592980236:INFO:recurring-task.cc(55)] [Retry] Scheduling 234952809 with a delay 60000, Now = 70000
[17865:3335:0524/193452:8701593021728:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x602000008a10 with delay 60
[17865:3335:0524/193452:8701593058996:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x602000008a10
[17865:3335:0524/193452:8701593093502:INFO:recurring-task_test.cc(71)] (130000) Task running: 3
[17865:3335:0524/193452:8701593137798:INFO:recurring-task.cc(55)] [Retry] Scheduling 234952809 with a delay 60000, Now = 130000
[17865:3335:0524/193452:8701593174576:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000089f0 with delay 60
[17865:3335:0524/193452:8701593212368:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000089f0
[17865:3335:0524/193452:8701593244270:INFO:recurring-task_test.cc(71)] (190000) Task running: 4
[17865:3335:0524/193452:8701593282857:INFO:recurring-task.cc(55)] [Retry] Scheduling 234952809 with a delay 60000, Now = 190000
[17865:3335:0524/193452:8701593319456:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x6020000089d0 with delay 60
[17865:3335:0524/193452:8701593353396:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x6020000089d0
[17865:3335:0524/193452:8701593393891:INFO:recurring-task_test.cc(71)] (250000) Task running: 5
[17865:3335:0524/193452:8701593429044:INFO:recurring-task.cc(55)] [Retry] Scheduling 234952809 with a delay 60000, Now = 250000
[17865:3335:0524/193452:8701593466878:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x6020000089b0 with delay 60
[17865:3335:0524/193452:8701593506927:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x6020000089b0
[17865:3335:0524/193452:8701593541617:INFO:recurring-task_test.cc(71)] (310000) Task running: 6
[17865:3335:0524/193452:8701593612362:INFO:recurring-task.cc(55)] [Retry] Scheduling 234952809 with a delay 60000, Now = 310000
[17865:3335:0524/193452:8701593652438:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000008990 with delay 60
[17865:3335:0524/193452:8701593697016:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000008990
[17865:3335:0524/193452:8701593732074:INFO:recurring-task_test.cc(71)] (370000) Task running: 7
[17865:3335:0524/193452:8701593771118:INFO:recurring-task.cc(55)] [Retry] Scheduling 234952809 with a delay 60000, Now = 370000
[17865:3335:0524/193452:8701593806271:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000008970 with delay 60
[17865:3335:0524/193452:8701593856070:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000008970
[17865:3335:0524/193452:8701593895787:INFO:recurring-task_test.cc(71)] (430000) Task running: 8
[ OK ] RecurringTaskTest.PeriodicTask (2 ms)
[24/28] RecurringTaskTest.PeriodicTask (2 ms)
[ RUN ] RecurringTaskTest.ExponentialBackoffTask
[17865:3335:0524/193452:8701594564675:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 234962025 with a delay 10000, Now = 0
[17865:3335:0524/193452:8701594612728:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x6020000088f0 with delay 10
[17865:3335:0524/193452:8701594661318:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x6020000088f0
[17865:3335:0524/193452:8701594701734:INFO:recurring-task_test.cc(71)] (10000) Task running: 1
[17865:3335:0524/193452:8701594746290:INFO:recurring-task.cc(55)] [Retry] Scheduling 234962025 with a delay 50000, Now = 10000
[17865:3335:0524/193452:8701594794765:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x6020000088d0 with delay 50
[17865:3335:0524/193452:8701594865471:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x6020000088d0
[17865:3335:0524/193452:8701594921024:INFO:recurring-task_test.cc(71)] (60000) Task running: 2
[17865:3335:0524/193452:8701594964862:INFO:recurring-task.cc(55)] [Retry] Scheduling 234962025 with a delay 149000, Now = 60000
[17865:3335:0524/193452:8701595009716:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x6020000088b0 with delay 149
[17865:3335:0524/193452:8701595068307:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x6020000088b0
[17865:3335:0524/193452:8701595115855:INFO:recurring-task_test.cc(71)] (210000) Task running: 3
[17865:3335:0524/193452:8701595162630:INFO:recurring-task.cc(55)] [Retry] Scheduling 234962025 with a delay 248000, Now = 210000
[17865:3335:0524/193452:8701595211827:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000008890 with delay 248
[17865:3335:0524/193452:8701595260347:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000008890
[17865:3335:0524/193452:8701595297506:INFO:recurring-task_test.cc(71)] (460000) Task running: 4
[17865:3335:0524/193452:8701595359326:INFO:recurring-task.cc(55)] [Retry] Scheduling 234962025 with a delay 446000, Now = 460000
[17865:3335:0524/193452:8701595406468:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000008870 with delay 446
[17865:3335:0524/193452:8701595478526:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000008870
[17865:3335:0524/193452:8701595527729:INFO:recurring-task_test.cc(71)] (910000) Task running: 5
[17865:3335:0524/193452:8701595572324:INFO:recurring-task.cc(55)] [Retry] Scheduling 234962025 with a delay 842000, Now = 910000
[17865:3335:0524/193452:8701595615956:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000008850 with delay 842
[17865:3335:0524/193452:8701595670998:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000008850
[17865:3335:0524/193452:8701595704590:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6
[17865:3335:0524/193452:8701595741652:INFO:recurring-task.cc(55)] [Retry] Scheduling 234962025 with a delay 1040000, Now = 1760000
[17865:3335:0524/193452:8701595778169:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000008830 with delay 1040
[17865:3335:0524/193452:8701595889638:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000008830
[17865:3335:0524/193452:8701595933144:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7
[17865:3335:0524/193452:8701595977348:INFO:recurring-task.cc(55)] [Retry] Scheduling 234962025 with a delay 1040000, Now = 2800000
[17865:3335:0524/193452:8701596014867:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000008810 with delay 1040
[17865:3335:0524/193452:8701596062746:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000008810
[17865:3335:0524/193452:8701596096449:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8
[ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms)
[25/28] RecurringTaskTest.ExponentialBackoffTask (2 ms)
[ RUN ] RecurringTaskTest.OneShotTask
[17865:3335:0524/193452:8701596429625:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 234971241 with a delay 10000, Now = 0
[17865:3335:0524/193452:8701596482962:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000008790 with delay 10
[17865:3335:0524/193452:8701596531996:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000008790
[17865:3335:0524/193452:8701596569904:INFO:recurring-task_test.cc(71)] (10000) Task running: 1
[17865:3335:0524/193452:8701596640297:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 234971241 with a delay 10000, Now = 10000
[17865:3335:0524/193452:8701596683874:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000008770 with delay 10
[17865:3335:0524/193452:8701596727749:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000008770
[17865:3335:0524/193452:8701596765157:INFO:recurring-task_test.cc(71)] (20000) Task running: 2
[ OK ] RecurringTaskTest.OneShotTask (0 ms)
[26/28] RecurringTaskTest.OneShotTask (0 ms)
[ RUN ] ThrottleTest.ThrottlingScripted
[17865:3335:0524/193452:8701597145678:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x6020000086f0 with delay 920
[17865:3335:0524/193452:8701597218645:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x6020000086f0
[17865:3335:0524/193452:8701597335250:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x6020000086d0 with delay 45000
[17865:3335:0524/193452:8701597567169:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x6020000086d0
[ OK ] ThrottleTest.ThrottlingScripted (1 ms)
[27/28] ThrottleTest.ThrottlingScripted (1 ms)
[ RUN ] ThrottleTest.ThrottlingStorm
[17865:3335:0524/193452:8701597794584:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000008650 with delay 990
[17865:3335:0524/193452:8701597893235:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000008650
[17865:3335:0524/193452:8701597941252:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x602000008630 with delay 1000
[17865:3335:0524/193452:8701598025404:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x602000008630
[17865:3335:0524/193452:8701598068611:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x602000008610 with delay 1000
[17865:3335:0524/193452:8701598153215:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x602000008610
[17865:3335:0524/193452:8701598195278:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x6020000085f0 with delay 1000
[17865:3335:0524/193452:8701598277409:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x6020000085f0
[17865:3335:0524/193452:8701598318929:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x6020000085d0 with delay 1000
[17865:3335:0524/193452:8701598426556:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x6020000085d0
[17865:3335:0524/193452:8701598468058:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x6020000085b0 with delay 1000
[17865:3335:0524/193452:8701598559830:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x6020000085b0
[17865:3335:0524/193452:8701598607730:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000008590 with delay 54000
[17865:3335:0524/193452:8701599647586:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000008590
[17865:3335:0524/193452:8701599701350:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000008570 with delay 1000
[17865:3335:0524/193452:8701599753385:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000008570
[17865:3335:0524/193452:8701599804932:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000008550 with delay 1000
[17865:3335:0524/193452:8701599860827:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000008550
[17865:3335:0524/193452:8701599913037:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000008530 with delay 1000
[17865:3335:0524/193452:8701599964145:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000008530
[17865:3335:0524/193452:8701600003970:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000008510 with delay 1000
[17865:3335:0524/193452:8701600054474:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000008510
[17865:3335:0524/193452:8701600093322:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x6020000084f0 with delay 1000
[17865:3335:0524/193452:8701600146254:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x6020000084f0
[17865:3335:0524/193452:8701600184902:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x6020000084d0 with delay 1000
[17865:3335:0524/193452:8701600231825:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x6020000084d0
[17865:3335:0524/193452:8701600267105:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x6020000084b0 with delay 54000
[17865:3335:0524/193452:8701600973331:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x6020000084b0
[17865:3335:0524/193452:8701601015264:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000008490 with delay 1000
[17865:3335:0524/193452:8701601076325:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000008490
[17865:3335:0524/193452:8701601115030:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000008470 with delay 1000
[17865:3335:0524/193452:8701601162569:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000008470
[17865:3335:0524/193452:8701601207105:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000008450 with delay 1000
[17865:3335:0524/193452:8701601254365:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000008450
[17865:3335:0524/193452:8701601294582:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000008430 with delay 1000
[17865:3335:0524/193452:8701601341576:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000008430
[17865:3335:0524/193452:8701601385831:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000008410 with delay 1000
[17865:3335:0524/193452:8701601433407:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000008410
[17865:3335:0524/193452:8701601470236:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x6020000083f0 with delay 1000
[17865:3335:0524/193452:8701601517446:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x6020000083f0
[17865:3335:0524/193452:8701601555835:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x6020000083d0 with delay 54000
[17865:3335:0524/193452:8701602269068:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x6020000083d0
[17865:3335:0524/193452:8701602309227:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x6020000083b0 with delay 1000
[17865:3335:0524/193452:8701602357349:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x6020000083b0
[17865:3335:0524/193452:8701602394258:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000008390 with delay 1000
[17865:3335:0524/193452:8701602441684:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000008390
[17865:3335:0524/193452:8701602478946:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000008370 with delay 1000
[17865:3335:0524/193452:8701602525877:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000008370
[17865:3335:0524/193452:8701602569512:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000008350 with delay 1000
[17865:3335:0524/193452:8701602618068:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000008350
[17865:3335:0524/193452:8701602655029:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000008330 with delay 1000
[17865:3335:0524/193452:8701602718872:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000008330
[17865:3335:0524/193452:8701602757442:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x602000008310 with delay 1000
[17865:3335:0524/193452:8701602809858:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x602000008310
[17865:3335:0524/193452:8701602845564:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000082f0 with delay 54000
[17865:3335:0524/193452:8701603564442:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000082f0
[17865:3335:0524/193452:8701603608102:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x6020000082d0 with delay 1000
[17865:3335:0524/193452:8701603656107:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x6020000082d0
[17865:3335:0524/193452:8701603703902:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x6020000082b0 with delay 1000
[17865:3335:0524/193452:8701603751196:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x6020000082b0
[17865:3335:0524/193452:8701603788025:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000008290 with delay 1000
[17865:3335:0524/193452:8701603835042:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000008290
[17865:3335:0524/193452:8701603881837:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000008270 with delay 1000
[17865:3335:0524/193452:8701603930124:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000008270
[17865:3335:0524/193452:8701603974067:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000008250 with delay 1000
[17865:3335:0524/193452:8701604021464:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000008250
[17865:3335:0524/193452:8701604058264:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000008230 with delay 1000
[17865:3335:0524/193452:8701604109371:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000008230
[17865:3335:0524/193452:8701604169029:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x602000008210 with delay 54000
[17865:3335:0524/193452:8701604873905:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x602000008210
[ OK ] ThrottleTest.ThrottlingStorm (7 ms)
[28/28] ThrottleTest.ThrottlingStorm (7 ms)
SUCCESS: all tests passed.
Tests took 0 seconds.
+------------------------------------------------------------------------+
| End of shard 0 Pending: 0.5s Duration: 1.0s Bot: vm921-m4 Exit: 0 |
+------------------------------------------------------------------------+
Total duration: 1.0s
exit code (as seen by runtest.py): 0
@@@STEP_TEXT@@@@
@@@STEP_CURSOR@cacheinvalidation_unittests on Mac-10.9@@@
@@@STEP_LINK@shard #0 isolated out@https://isolateserver.appspot.com/browse?namespace=default-gzip&hash=4208c8e362406d78871bba41073546c7d4f5aea7@@@