See <https://builds.apache.org/job/mesos-reviewbot/15340/>
------------------------------------------ [...truncated 311313 lines...] I0921 04:17:51.848589 28954 slave.cpp:533] Agent resources: cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000] I0921 04:17:51.848704 28954 slave.cpp:541] Agent attributes: [ ] I0921 04:17:51.848727 28954 slave.cpp:546] Agent hostname: 043a9b4c246b I0921 04:17:51.848845 28966 authenticatee.cpp:121] Creating new client SASL connection I0921 04:17:51.849128 28959 master.cpp:6583] Authenticating scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:51.849228 28957 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(433)@172.17.0.2:51750 I0921 04:17:51.849436 28962 authenticator.cpp:98] Creating new server SASL connection I0921 04:17:51.849685 28959 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0921 04:17:51.849792 28959 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0921 04:17:51.849923 28960 authenticator.cpp:204] Received SASL authentication start I0921 04:17:51.849995 28960 authenticator.cpp:326] Authentication requires more steps I0921 04:17:51.850095 28959 authenticatee.cpp:259] Received SASL authentication step I0921 04:17:51.850253 28959 authenticator.cpp:232] Received SASL authentication step I0921 04:17:51.850327 28959 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '043a9b4c246b' server FQDN: '043a9b4c246b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0921 04:17:51.850481 28959 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0921 04:17:51.850529 28959 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0921 04:17:51.850563 28959 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '043a9b4c246b' server FQDN: '043a9b4c246b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0921 04:17:51.850584 28959 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0921 04:17:51.850597 28959 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0921 04:17:51.850682 28958 state.cpp:57] Recovering state from '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/meta' I0921 04:17:51.850685 28959 authenticator.cpp:318] Authentication success I0921 04:17:51.850808 28954 authenticatee.cpp:299] Authentication success I0921 04:17:51.850967 28960 master.cpp:6613] Successfully authenticated principal 'test-principal' at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:51.851058 28951 status_update_manager.cpp:203] Recovering status update manager I0921 04:17:51.851160 28956 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(433)@172.17.0.2:51750 I0921 04:17:51.851335 28961 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:51750 I0921 04:17:51.851363 28961 sched.cpp:820] Sending SUBSCRIBE call to master@172.17.0.2:51750 I0921 04:17:51.851452 28961 sched.cpp:853] Will retry registration in 1.979063342secs if necessary I0921 04:17:51.851588 28964 slave.cpp:5227] Finished recovery I0921 04:17:51.851642 28961 master.cpp:2587] Received SUBSCRIBE call for framework 'default' at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:51.851699 28961 master.cpp:2049] Authorizing framework principal 'test-principal' to receive offers for role '*' I0921 04:17:51.852237 28961 master.cpp:2663] Subscribing framework default with checkpointing disabled and capabilities [ ] I0921 04:17:51.852787 28963 sched.cpp:743] Framework registered with 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:51.852807 28966 hierarchical.cpp:272] Added framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:51.852875 28963 sched.cpp:757] Scheduler::registered took 62041ns I0921 04:17:51.852881 28966 hierarchical.cpp:1685] No allocations performed I0921 04:17:51.853073 28966 hierarchical.cpp:1780] No inverse offers to send out! I0921 04:17:51.853170 28966 hierarchical.cpp:1277] Performed allocation for 0 agents in 335992ns I0921 04:17:51.872225 28964 slave.cpp:5399] Querying resource estimator for oversubscribable resources I0921 04:17:51.872756 28964 slave.cpp:915] New master detected at master@172.17.0.2:51750 I0921 04:17:51.872778 28964 slave.cpp:974] Authenticating with master master@172.17.0.2:51750 I0921 04:17:51.872788 28956 status_update_manager.cpp:177] Pausing sending status updates I0921 04:17:51.872839 28964 slave.cpp:985] Using default CRAM-MD5 authenticatee I0921 04:17:51.872999 28964 slave.cpp:947] Detecting new master I0921 04:17:51.873106 28963 authenticatee.cpp:121] Creating new client SASL connection I0921 04:17:51.873208 28964 slave.cpp:5413] Received oversubscribable resources from the resource estimator I0921 04:17:51.873513 28958 master.cpp:6583] Authenticating slave(190)@172.17.0.2:51750 I0921 04:17:51.873651 28964 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(434)@172.17.0.2:51750 I0921 04:17:51.873986 28954 authenticator.cpp:98] Creating new server SASL connection I0921 04:17:51.874335 28965 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0921 04:17:51.874373 28965 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0921 04:17:51.874505 28965 authenticator.cpp:204] Received SASL authentication start I0921 04:17:51.874578 28965 authenticator.cpp:326] Authentication requires more steps I0921 04:17:51.874725 28956 authenticatee.cpp:259] Received SASL authentication step I0921 04:17:51.874899 28962 authenticator.cpp:232] Received SASL authentication step I0921 04:17:51.874938 28962 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '043a9b4c246b' server FQDN: '043a9b4c246b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0921 04:17:51.874956 28962 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0921 04:17:51.875000 28962 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0921 04:17:51.875027 28962 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '043a9b4c246b' server FQDN: '043a9b4c246b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0921 04:17:51.875049 28962 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0921 04:17:51.875063 28962 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0921 04:17:51.875083 28962 authenticator.cpp:318] Authentication success I0921 04:17:51.875216 28957 authenticatee.cpp:299] Authentication success I0921 04:17:51.875336 28961 master.cpp:6613] Successfully authenticated principal 'test-principal' at slave(190)@172.17.0.2:51750 I0921 04:17:51.875442 28963 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(434)@172.17.0.2:51750 I0921 04:17:51.875706 28966 slave.cpp:1069] Successfully authenticated with master master@172.17.0.2:51750 I0921 04:17:51.875934 28966 slave.cpp:1475] Will retry registration in 4.924259ms if necessary I0921 04:17:51.876178 28961 master.cpp:5040] Registering agent at slave(190)@172.17.0.2:51750 (043a9b4c246b) with id 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 I0921 04:17:51.876837 28962 registrar.cpp:461] Applied 1 operations in 79795ns; attempting to update the registry I0921 04:17:51.877873 28958 log.cpp:577] Attempting to append 337 bytes to the log I0921 04:17:51.878056 28960 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0921 04:17:51.879194 28954 replica.cpp:537] Replica received write request for position 3 from __req_res__(3007)@172.17.0.2:51750 I0921 04:17:51.881566 28962 slave.cpp:1475] Will retry registration in 29.920965ms if necessary I0921 04:17:51.881712 28964 master.cpp:5028] Ignoring register agent message from slave(190)@172.17.0.2:51750 (043a9b4c246b) as admission is already in progress I0921 04:17:51.882606 28965 hierarchical.cpp:1685] No allocations performed I0921 04:17:51.882647 28965 hierarchical.cpp:1780] No inverse offers to send out! I0921 04:17:51.882733 28965 hierarchical.cpp:1277] Performed allocation for 0 agents in 196326ns I0921 04:17:51.912089 28958 slave.cpp:1475] Will retry registration in 54.989715ms if necessary I0921 04:17:51.912263 28952 master.cpp:5028] Ignoring register agent message from slave(190)@172.17.0.2:51750 (043a9b4c246b) as admission is already in progress I0921 04:17:51.945797 28954 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 66.541786ms I0921 04:17:51.945842 28954 replica.cpp:708] Persisted action APPEND at position 3 I0921 04:17:51.946879 28956 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0 I0921 04:17:51.967705 28965 slave.cpp:1475] Will retry registration in 5.436762ms if necessary I0921 04:17:51.967895 28954 master.cpp:5028] Ignoring register agent message from slave(190)@172.17.0.2:51750 (043a9b4c246b) as admission is already in progress I0921 04:17:51.974359 28951 slave.cpp:1475] Will retry registration in 63.436491ms if necessary I0921 04:17:51.974531 28966 master.cpp:5028] Ignoring register agent message from slave(190)@172.17.0.2:51750 (043a9b4c246b) as admission is already in progress I0921 04:17:52.029913 28956 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 82.910709ms I0921 04:17:52.029989 28956 replica.cpp:708] Persisted action APPEND at position 3 I0921 04:17:52.032229 28951 registrar.cpp:506] Successfully updated the registry in 155.302912ms I0921 04:17:52.032532 28959 log.cpp:596] Attempting to truncate the log to 3 I0921 04:17:52.032754 28966 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4 I0921 04:17:52.033639 28958 slave.cpp:4089] Received ping from slave-observer(190)@172.17.0.2:51750 I0921 04:17:52.033654 28955 master.cpp:5111] Registered agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) with cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000] I0921 04:17:52.033819 28958 slave.cpp:1115] Registered with master master@172.17.0.2:51750; given agent ID 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 I0921 04:17:52.033845 28958 fetcher.cpp:86] Clearing fetcher cache I0921 04:17:52.033861 28957 replica.cpp:537] Replica received write request for position 4 from __req_res__(3008)@172.17.0.2:51750 I0921 04:17:52.033998 28959 status_update_manager.cpp:184] Resuming sending status updates I0921 04:17:52.034078 28965 hierarchical.cpp:482] Added agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 (043a9b4c246b) with cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000] (allocated: ) I0921 04:17:52.034281 28958 slave.cpp:1138] Checkpointing SlaveInfo to '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/meta/slaves/4200f99d-a497-4137-8afd-f306d2bb0f3a-S0/slave.info' I0921 04:17:52.034667 28958 slave.cpp:1175] Forwarding total oversubscribed resources I0921 04:17:52.034862 28964 master.cpp:5508] Received update of agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) with total oversubscribed resources I0921 04:17:52.035249 28965 hierarchical.cpp:1780] No inverse offers to send out! I0921 04:17:52.035318 28965 hierarchical.cpp:1300] Performed allocation for agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 in 1.194563ms I0921 04:17:52.035434 28965 hierarchical.cpp:546] Agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 (043a9b4c246b) updated with oversubscribed resources (total: cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000]) I0921 04:17:52.035536 28965 hierarchical.cpp:1685] No allocations performed I0921 04:17:52.035565 28965 hierarchical.cpp:1780] No inverse offers to send out! I0921 04:17:52.035604 28965 hierarchical.cpp:1300] Performed allocation for agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 in 135498ns I0921 04:17:52.035704 28958 master.cpp:6412] Sending 1 offers to framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (default) at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:52.037067 28960 sched.cpp:917] Scheduler::resourceOffers took 1.02045ms I0921 04:17:52.038234 28966 master.cpp:3521] Processing ACCEPT call for offers: [ 4200f99d-a497-4137-8afd-f306d2bb0f3a-O0 ] on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) for framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (default) at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:52.038383 28966 master.cpp:3143] Authorizing framework principal 'test-principal' to launch task 0 W0921 04:17:52.039953 28966 validation.cpp:916] Executor 'default' for task '0' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. W0921 04:17:52.039985 28966 validation.cpp:928] Executor 'default' for task '0' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. I0921 04:17:52.040272 28966 master.cpp:8159] Adding task 0 with resources cpus(*):1; mem(*):64 on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 (043a9b4c246b) I0921 04:17:52.040407 28966 master.cpp:4121] Launching task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (default) at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 with resources cpus(*):1; mem(*):64 on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) I0921 04:17:52.040762 28961 slave.cpp:1539] Got assigned task '0' for framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.041293 28961 slave.cpp:1696] Launching task '0' for framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.041656 28965 hierarchical.cpp:1009] Recovered ports(*):[31000-32000]; disk(*):3701220 (total: cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):64) on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 from framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.041704 28965 hierarchical.cpp:1046] Framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 filtered agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 for 5secs I0921 04:17:52.041970 28961 paths.cpp:536] Trying to chown '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/slaves/4200f99d-a497-4137-8afd-f306d2bb0f3a-S0/frameworks/4200f99d-a497-4137-8afd-f306d2bb0f3a-0000/executors/default/runs/60fc98d6-23ec-4607-bac6-a252dedb2c53' to user 'mesos' I0921 04:17:52.053012 28961 slave.cpp:6110] Launching executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 with resources in work directory '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/slaves/4200f99d-a497-4137-8afd-f306d2bb0f3a-S0/frameworks/4200f99d-a497-4137-8afd-f306d2bb0f3a-0000/executors/default/runs/60fc98d6-23ec-4607-bac6-a252dedb2c53' I0921 04:17:52.056272 28961 exec.cpp:162] Version: 1.1.0 I0921 04:17:52.056753 28960 exec.cpp:212] Executor started at: executor(80)@172.17.0.2:51750 with pid 28932 I0921 04:17:52.057034 28961 slave.cpp:1982] Queued task '0' for executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.057102 28961 slave.cpp:868] Successfully attached file '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/slaves/4200f99d-a497-4137-8afd-f306d2bb0f3a-S0/frameworks/4200f99d-a497-4137-8afd-f306d2bb0f3a-0000/executors/default/runs/60fc98d6-23ec-4607-bac6-a252dedb2c53' I0921 04:17:52.057303 28961 slave.cpp:3203] Got registration for executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 from executor(80)@172.17.0.2:51750 I0921 04:17:52.057709 28962 exec.cpp:237] Executor registered on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 I0921 04:17:52.057780 28962 exec.cpp:249] Executor::registered took 44889ns I0921 04:17:52.058010 28961 slave.cpp:2186] Sending queued task '0' to executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 at executor(80)@172.17.0.2:51750 I0921 04:17:52.058396 28966 exec.cpp:324] Executor asked to run task '0' I0921 04:17:52.058488 28966 exec.cpp:333] Executor::launchTask took 68613ns I0921 04:17:52.058593 28966 exec.cpp:550] Executor sending status update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.058900 28956 slave.cpp:3606] Handling status update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 from executor(80)@172.17.0.2:51750 I0921 04:17:52.059706 28966 status_update_manager.cpp:323] Received status update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.059754 28966 status_update_manager.cpp:500] Creating StatusUpdate stream for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.060204 28966 status_update_manager.cpp:377] Forwarding update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 to the agent I0921 04:17:52.060492 28965 slave.cpp:4007] Forwarding the update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 to master@172.17.0.2:51750 I0921 04:17:52.061067 28965 slave.cpp:3901] Status update manager successfully handled status update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.061136 28965 slave.cpp:3917] Sending acknowledgement for status update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 to executor(80)@172.17.0.2:51750 I0921 04:17:52.061197 28963 master.cpp:5638] Status update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 from agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) I0921 04:17:52.061275 28963 master.cpp:5700] Forwarding status update TASK_FINISHED (UUID: fdbba50f-9ab7-45a2-9361-9fc112ee285d) for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.061444 28956 exec.cpp:373] Executor received status update acknowledgement fdbba50f-9ab7-45a2-9361-9fc112ee285d for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.061607 28963 master.cpp:7537] Updating the state of task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED) I0921 04:17:52.062386 28959 hierarchical.cpp:1009] Recovered cpus(*):1; mem(*):64 (total: cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000], allocated: ) on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 from framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.063985 28961 hierarchical.cpp:1780] No inverse offers to send out! I0921 04:17:52.064086 28961 hierarchical.cpp:1277] Performed allocation for 1 agents in 1.052104ms I0921 04:17:52.064530 28951 master.cpp:6412] Sending 1 offers to framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (default) at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:52.065065 28951 sched.cpp:917] Scheduler::resourceOffers took 105586ns I0921 04:17:52.065611 28932 sched.cpp:1995] Asked to stop the driver I0921 04:17:52.065728 28953 sched.cpp:1187] Stopping framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.065969 28954 master.cpp:6988] Processing TEARDOWN call for framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (default) at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:52.066011 28954 master.cpp:7000] Removing framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (default) at scheduler-d1b40327-0a57-4ed2-83af-f616c102316b@172.17.0.2:51750 I0921 04:17:52.066161 28961 hierarchical.cpp:383] Deactivated framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.066262 28954 master.cpp:7537] Updating the state of task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 (latest state: TASK_FINISHED, status update state: TASK_KILLED) I0921 04:17:52.066339 28959 slave.cpp:2506] Asked to shut down framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 by master@172.17.0.2:51750 I0921 04:17:52.066314 28954 master.cpp:7633] Removing task 0 with resources cpus(*):1; mem(*):64 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) I0921 04:17:52.066385 28959 slave.cpp:2531] Shutting down framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.066442 28959 slave.cpp:4810] Shutting down executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 at executor(80)@172.17.0.2:51750 I0921 04:17:52.066558 28951 exec.cpp:414] Executor asked to shutdown I0921 04:17:52.066612 28951 exec.cpp:429] Executor::shutdown took 29310ns I0921 04:17:52.066782 28951 slave.cpp:4135] Got exited event for executor(80)@172.17.0.2:51750 I0921 04:17:52.067093 28954 master.cpp:7662] Removing executor 'default' with resources of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) I0921 04:17:52.067373 28961 slave.cpp:4492] Executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 exited with status 0 I0921 04:17:52.067453 28961 slave.cpp:4596] Cleaning up executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 at executor(80)@172.17.0.2:51750 W0921 04:17:52.067595 28954 master.cpp:5756] Ignoring unknown exited executor 'default' of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) I0921 04:17:52.067617 28966 hierarchical.cpp:1009] Recovered cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000] (total: cpus(*):1; mem(*):64; disk(*):3701220; ports(*):[31000-32000], allocated: ) on agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 from framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.067920 28966 hierarchical.cpp:334] Removed framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.074592 28964 gc.cpp:55] Scheduling '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/slaves/4200f99d-a497-4137-8afd-f306d2bb0f3a-S0/frameworks/4200f99d-a497-4137-8afd-f306d2bb0f3a-0000/executors/default/runs/60fc98d6-23ec-4607-bac6-a252dedb2c53' for gc 6.9999991381363days in the future I0921 04:17:52.074689 28961 slave.cpp:4684] Cleaning up framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.074748 28964 gc.cpp:55] Scheduling '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/slaves/4200f99d-a497-4137-8afd-f306d2bb0f3a-S0/frameworks/4200f99d-a497-4137-8afd-f306d2bb0f3a-0000/executors/default' for gc 6.99999913610963days in the future I0921 04:17:52.074777 28965 status_update_manager.cpp:285] Closing status update streams for framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.074852 28965 status_update_manager.cpp:531] Cleaning up status update stream for task 0 of framework 4200f99d-a497-4137-8afd-f306d2bb0f3a-0000 I0921 04:17:52.074856 28961 slave.cpp:787] Agent terminating I0921 04:17:52.074878 28964 gc.cpp:55] Scheduling '/tmp/MasterTest_UnacknowledgedTerminalTask_dX3WyA/slaves/4200f99d-a497-4137-8afd-f306d2bb0f3a-S0/frameworks/4200f99d-a497-4137-8afd-f306d2bb0f3a-0000' for gc 6.99999913435259days in the future I0921 04:17:52.075093 28953 master.cpp:1258] Agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) disconnected I0921 04:17:52.075122 28953 master.cpp:2947] Disconnecting agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) I0921 04:17:52.075187 28953 master.cpp:2966] Deactivating agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 at slave(190)@172.17.0.2:51750 (043a9b4c246b) I0921 04:17:52.075358 28965 hierarchical.cpp:575] Agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 deactivated I0921 04:17:52.078038 28932 master.cpp:1097] Master terminating I0921 04:17:52.078817 28963 hierarchical.cpp:514] Removed agent 4200f99d-a497-4137-8afd-f306d2bb0f3a-S0 I0921 04:17:52.083061 28957 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 49.137051ms I0921 04:17:52.083101 28957 replica.cpp:708] Persisted action TRUNCATE at position 4 [ OK ] MasterTest.UnacknowledgedTerminalTask (1627 ms) [ RUN ] MasterTest.ReleaseResourcesForTerminalTaskWithPendingUpdates I0921 04:17:52.113205 28932 cluster.cpp:158] Creating default 'local' authorizer I0921 04:17:52.359547 28932 leveldb.cpp:174] Opened db in 246.067804ms I0921 04:17:52.469465 28932 leveldb.cpp:181] Compacted db in 109.84446ms I0921 04:17:52.469565 28932 leveldb.cpp:196] Created db iterator in 29973ns I0921 04:17:52.469588 28932 leveldb.cpp:202] Seeked to beginning of db in 3097ns I0921 04:17:52.469599 28932 leveldb.cpp:271] Iterated through 0 keys in the db in 648ns I0921 04:17:52.469655 28932 replica.cpp:776] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0921 04:17:52.470509 28965 recover.cpp:451] Starting replica recovery I0921 04:17:52.470829 28965 recover.cpp:477] Replica is in EMPTY status I0921 04:17:52.472110 28960 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from __req_res__(3009)@172.17.0.2:51750 I0921 04:17:52.472731 28953 recover.cpp:197] Received a recover response from a replica in EMPTY status I0921 04:17:52.473420 28966 recover.cpp:568] Updating replica status to STARTING I0921 04:17:52.474642 28966 master.cpp:380] Master 640ab2e9-c9f3-4cc4-84f2-35fe21db547d (043a9b4c246b) started on 172.17.0.2:51750 I0921 04:17:52.474670 28966 master.cpp:382] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/hJt3y8/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-1.1.0/_inst/share/mesos/webui" --work_dir="/tmp/hJt3y8/master" --zk_session_timeout="10secs" I0921 04:17:52.475055 28966 master.cpp:432] Master only allowing authenticated frameworks to register I0921 04:17:52.475065 28966 master.cpp:446] Master only allowing authenticated agents to register I0921 04:17:52.475071 28966 master.cpp:459] Master only allowing authenticated HTTP frameworks to register I0921 04:17:52.475078 28966 credentials.hpp:37] Loading credentials for authentication from '/tmp/hJt3y8/credentials' I0921 04:17:52.475370 28966 master.cpp:504] Using default 'crammd5' authenticator I0921 04:17:52.475510 28966 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0921 04:17:52.475670 28966 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0921 04:17:52.475811 28966 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0921 04:17:52.476033 28966 master.cpp:584] Authorization enabled I0921 04:17:52.476243 28962 hierarchical.cpp:149] Initialized hierarchical allocator process I0921 04:17:52.476261 28952 whitelist_watcher.cpp:77] No whitelist given I0921 04:17:52.478655 28957 master.cpp:2013] Elected as the leading master! I0921 04:17:52.478698 28957 master.cpp:1560] Recovering from registrar I0921 04:17:52.478850 28951 registrar.cpp:329] Recovering registrar I0921 04:17:52.545322 28963 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 71.731719ms I0921 04:17:52.545414 28963 replica.cpp:320] Persisted replica status to STARTING I0921 04:17:52.545828 28963 recover.cpp:477] Replica is in STARTING status I0921 04:17:52.546953 28951 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from __req_res__(3010)@172.17.0.2:51750 I0921 04:17:52.547405 28958 recover.cpp:197] Received a recover response from a replica in STARTING status I0921 04:17:52.547857 28961 recover.cpp:568] Updating replica status to VOTING I0921 04:17:52.623605 28955 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 75.502866ms I0921 04:17:52.623683 28955 replica.cpp:320] Persisted replica status to VOTING I0921 04:17:52.623908 28966 recover.cpp:582] Successfully joined the Paxos group I0921 04:17:52.624367 28966 recover.cpp:466] Recover process terminated I0921 04:17:52.624753 28964 log.cpp:553] Attempting to start the writer I0921 04:17:52.625964 28953 replica.cpp:493] Replica received implicit promise request from __req_res__(3011)@172.17.0.2:51750 with proposal 1 I0921 04:17:52.734971 28953 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 108.958888ms I0921 04:17:52.735045 28953 replica.cpp:342] Persisted promised to 1 I0921 04:17:52.735785 28960 coordinator.cpp:238] Coordinator attempting to fill missing positions I0921 04:17:52.736977 28953 replica.cpp:388] Replica received explicit promise request from __req_res__(3012)@172.17.0.2:51750 for position 0 with proposal 2 I0921 04:17:52.835407 28953 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 98.374742ms I0921 04:17:52.835491 28953 replica.cpp:708] Persisted action NOP at position 0 I0921 04:17:52.837040 28953 replica.cpp:537] Replica received write request for position 0 from __req_res__(3013)@172.17.0.2:51750 I0921 04:17:52.837108 28953 leveldb.cpp:436] Reading position from leveldb took 35710ns Build timed out (after 180 minutes). Marking the build as failed. Build was aborted I0921 04:17:52.935015 28953 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 97.852878ms I0921 04:17:52.935101 28953 replica.cpp:708] Persisted action NOP at position 0 I0921 04:17:52.935971 28964 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0 I0921 04:17:53.083693 28964 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 147.668016ms I0921 04:17:53.083786 28964 replica.cpp:708] Persisted action NOP at position 0 I0921 04:17:53.084779 28966 log.cpp:569] Writer started with ending position 0 I0921 04:17:53.086145 28964 leveldb.cpp:436] Reading position from leveldb took 58030ns I0921 04:17:53.088309 28964 registrar.cpp:362] Successfully fetched the registry (0B) in 609.379072ms I0921 04:17:53.088426 28964 registrar.cpp:461] Applied 1 operations in 23115ns; attempting to update the registry I0921 04:17:53.089160 28966 log.cpp:577] Attempting to append 168 bytes to the log I0921 04:17:53.089290 28965 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0921 04:17:53.090167 28957 replica.cpp:537] Replica received write request for position 1 from __req_res__(3014)@172.17.0.2:51750 I0921 04:17:53.194900 28957 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took 104.595228ms I0921 04:17:53.194998 28957 replica.cpp:708] Persisted action APPEND at position 1 I0921 04:17:53.196228 28966 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
