See
<https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4581/display/redirect>
------------------------------------------
[...truncated 5.38 MB...]
3: I1212 03:00:39.331070 18411 cluster.cpp:172] Creating default 'local'
authorizer
3: I1212 03:00:39.335134 18431 master.cpp:456] Master
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef (e57dc9d7dd39) started on 172.17.0.5:43260
3: I1212 03:00:39.335189 18431 master.cpp:458] 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/0tKyVn/credentials"
--filter_gpu_resources="true" --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"
--max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--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="/usr/local/share/mesos/webui" --work_dir="/tmp/0tKyVn/master"
--zk_session_timeout="10secs"
3: I1212 03:00:39.335494 18431 master.cpp:507] Master only allowing
authenticated frameworks to register
3: I1212 03:00:39.335501 18431 master.cpp:513] Master only allowing
authenticated agents to register
3: I1212 03:00:39.335506 18431 master.cpp:519] Master only allowing
authenticated HTTP frameworks to register
3: I1212 03:00:39.335511 18431 credentials.hpp:37] Loading credentials for
authentication from '/tmp/0tKyVn/credentials'
3: I1212 03:00:39.335778 18431 master.cpp:563] Using default 'crammd5'
authenticator
3: I1212 03:00:39.335918 18431 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
3: I1212 03:00:39.336063 18431 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
3: I1212 03:00:39.336180 18431 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
3: I1212 03:00:39.336294 18431 master.cpp:642] Authorization enabled
3: I1212 03:00:39.336495 18422 whitelist_watcher.cpp:77] No whitelist given
3: I1212 03:00:39.336504 18416 hierarchical.cpp:175] Initialized hierarchical
allocator process
3: I1212 03:00:39.339035 18423 master.cpp:2209] Elected as the leading master!
3: I1212 03:00:39.339066 18423 master.cpp:1689] Recovering from registrar
3: I1212 03:00:39.339284 18421 registrar.cpp:347] Recovering registrar
3: I1212 03:00:39.340291 18421 registrar.cpp:391] Successfully fetched the
registry (0B) in 957952ns
3: I1212 03:00:39.340464 18421 registrar.cpp:495] Applied 1 operations in
64737ns; attempting to update the registry
3: I1212 03:00:39.341235 18421 registrar.cpp:552] Successfully updated the
registry in 707072ns
3: I1212 03:00:39.341420 18421 registrar.cpp:424] Successfully recovered
registrar
3: I1212 03:00:39.341912 18432 master.cpp:1802] Recovered 0 agents from the
registry (135B); allowing 10mins for agents to re-register
3: I1212 03:00:39.341992 18435 hierarchical.cpp:213] Skipping recovery of
hierarchical allocator: nothing to recover
3: W1212 03:00:39.346477 18411 process.cpp:2756] Attempted to spawn already
running process files@172.17.0.5:43260
3: I1212 03:00:39.347442 18411 containerizer.cpp:304] Using isolation {
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1212 03:00:39.347939 18411 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges
3: W1212 03:00:39.348045 18411 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
3: I1212 03:00:39.348075 18411 provisioner.cpp:299] Using default backend 'copy'
3: I1212 03:00:39.350514 18411 cluster.cpp:460] Creating default 'local'
authorizer
3: I1212 03:00:39.353765 18426 slave.cpp:258] Mesos agent started on
(102)@172.17.0.5:43260
3: W1212 03:00:39.354321 18411 process.cpp:2756] Attempted to spawn already
running process version@172.17.0.5:43260
3: I1212 03:00:39.353804 18426 slave.cpp:259] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
--cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
--cgroups_root="mesos" --container_disk_watch_interval="15secs"
--containerizers="mesos"
--credential="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/credential"
--default_role="*" --disallow_sharing_agent_pid_namespace="false"
--disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true"
--docker_registry="https://registry-1.docker.io"; --docker_remove_delay="6hrs"
--docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
--docker_store_dir="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/jwt_secret_key"
--launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
--quiet="false" --reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_Nox5Q3"
--zk_session_timeout="10secs"
3: I1212 03:00:39.354487 18426 credentials.hpp:86] Loading credential for
authentication from
'/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/credential'
3: I1212 03:00:39.354677 18426 slave.cpp:291] Agent using credential for:
test-principal
3: I1212 03:00:39.354696 18426 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_yoyDMJ/http_credentials'
3: I1212 03:00:39.354945 18426 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
3: I1212 03:00:39.355054 18426 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
3: I1212 03:00:39.355270 18426 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
3: I1212 03:00:39.355365 18426 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
3: I1212 03:00:39.355507 18411 sched.cpp:232] Version: 1.5.0
3: I1212 03:00:39.355545 18426 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
3: I1212 03:00:39.355638 18426 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
3: I1212 03:00:39.356248 18422 sched.cpp:336] New master detected at
master@172.17.0.5:43260
3: I1212 03:00:39.356367 18422 sched.cpp:396] Authenticating with master
master@172.17.0.5:43260
3: I1212 03:00:39.356384 18422 sched.cpp:403] Using default CRAM-MD5
authenticatee
3: I1212 03:00:39.356627 18432 authenticatee.cpp:121] Creating new client SASL
connection
3: I1212 03:00:39.356917 18427 master.cpp:8888] Authenticating
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.357031 18413 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(210)@172.17.0.5:43260
3: I1212 03:00:39.357288 18431 authenticator.cpp:98] Creating new server SASL
connection
3: I1212 03:00:39.357331 18426 slave.cpp:590] Agent resources:
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
3: I1212 03:00:39.357532 18420 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
3: I1212 03:00:39.357554 18426 slave.cpp:598] Agent attributes: [ ]
3: I1212 03:00:39.357563 18420 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
3: I1212 03:00:39.357568 18426 slave.cpp:607] Agent hostname: e57dc9d7dd39
3: I1212 03:00:39.357669 18423 authenticator.cpp:204] Received SASL
authentication start
3: I1212 03:00:39.357741 18423 authenticator.cpp:326] Authentication requires
more steps
3: I1212 03:00:39.357787 18424 task_status_update_manager.cpp:181] Pausing
sending task status updates
3: I1212 03:00:39.357849 18415 authenticatee.cpp:259] Received SASL
authentication step
3: I1212 03:00:39.357978 18415 authenticator.cpp:232] Received SASL
authentication step
3: I1212 03:00:39.358011 18415 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'e57dc9d7dd39' server FQDN: 'e57dc9d7dd39'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
3: I1212 03:00:39.358028 18415 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
3: I1212 03:00:39.358083 18415 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
3: I1212 03:00:39.358109 18415 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'e57dc9d7dd39' server FQDN: 'e57dc9d7dd39'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
3: I1212 03:00:39.358119 18415 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1212 03:00:39.358125 18415 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1212 03:00:39.358144 18415 authenticator.cpp:318] Authentication success
3: I1212 03:00:39.358222 18430 authenticatee.cpp:299] Authentication success
3: I1212 03:00:39.358382 18412 master.cpp:8918] Successfully authenticated
principal 'test-principal' at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.358427 18434 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(210)@172.17.0.5:43260
3: I1212 03:00:39.358479 18430 sched.cpp:502] Successfully authenticated with
master master@172.17.0.5:43260
3: I1212 03:00:39.358500 18430 sched.cpp:824] Sending SUBSCRIBE call to
master@172.17.0.5:43260
3: I1212 03:00:39.358609 18430 sched.cpp:857] Will retry registration in
1.211522535secs if necessary
3: I1212 03:00:39.358860 18417 master.cpp:2957] Received SUBSCRIBE call for
framework 'default' at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.358891 18417 master.cpp:2274] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
3: I1212 03:00:39.359190 18428 state.cpp:66] Recovering state from
'/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_Nox5Q3/meta'
3: I1212 03:00:39.359545 18429 master.cpp:3037] Subscribing framework default
with checkpointing disabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT, PARTITION_AWARE ]
3: I1212 03:00:39.359632 18422 task_status_update_manager.cpp:207] Recovering
task status update manager
3: I1212 03:00:39.359786 18429 master.cpp:9109] Adding framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (default) at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260 with roles { }
suppressed
3: I1212 03:00:39.359905 18431 containerizer.cpp:674] Recovering containerizer
3: I1212 03:00:39.360342 18423 sched.cpp:751] Framework registered with
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.360406 18423 sched.cpp:765] Scheduler::registered took 48416ns
3: I1212 03:00:39.360543 18420 hierarchical.cpp:297] Added framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.360800 18420 hierarchical.cpp:1517] Performed allocation for
0 agents in 109076ns
3: I1212 03:00:39.361585 18416 provisioner.cpp:495] Provisioner recovery
complete
3: I1212 03:00:39.362078 18428 slave.cpp:6724] Finished recovery
3: I1212 03:00:39.363112 18424 task_status_update_manager.cpp:181] Pausing
sending task status updates
3: I1212 03:00:39.363106 18413 slave.cpp:1033] New master detected at
master@172.17.0.5:43260
3: I1212 03:00:39.363330 18413 slave.cpp:1088] Detecting new master
3: I1212 03:00:39.369746 18429 slave.cpp:1115] Authenticating with master
master@172.17.0.5:43260
3: I1212 03:00:39.369850 18429 slave.cpp:1124] Using default CRAM-MD5
authenticatee
3: I1212 03:00:39.370168 18418 authenticatee.cpp:121] Creating new client SASL
connection
3: I1212 03:00:39.370461 18418 master.cpp:8888] Authenticating
slave(102)@172.17.0.5:43260
3: I1212 03:00:39.370599 18434 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(211)@172.17.0.5:43260
3: I1212 03:00:39.370847 18421 authenticator.cpp:98] Creating new server SASL
connection
3: I1212 03:00:39.371062 18423 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
3: I1212 03:00:39.371090 18423 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
3: I1212 03:00:39.371292 18419 authenticator.cpp:204] Received SASL
authentication start
3: I1212 03:00:39.371335 18419 authenticator.cpp:326] Authentication requires
more steps
3: I1212 03:00:39.371444 18431 authenticatee.cpp:259] Received SASL
authentication step
3: I1212 03:00:39.371551 18430 authenticator.cpp:232] Received SASL
authentication step
3: I1212 03:00:39.371580 18430 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'e57dc9d7dd39' server FQDN: 'e57dc9d7dd39'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
3: I1212 03:00:39.371598 18430 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
3: I1212 03:00:39.371630 18430 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
3: I1212 03:00:39.371659 18430 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'e57dc9d7dd39' server FQDN: 'e57dc9d7dd39'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
3: I1212 03:00:39.371675 18430 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1212 03:00:39.371683 18430 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1212 03:00:39.371702 18430 authenticator.cpp:318] Authentication success
3: I1212 03:00:39.371783 18415 authenticatee.cpp:299] Authentication success
3: I1212 03:00:39.371842 18412 master.cpp:8918] Successfully authenticated
principal 'test-principal' at slave(102)@172.17.0.5:43260
3: I1212 03:00:39.371879 18417 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(211)@172.17.0.5:43260
3: I1212 03:00:39.372026 18435 slave.cpp:1207] Successfully authenticated with
master master@172.17.0.5:43260
3: I1212 03:00:39.372205 18435 slave.cpp:1684] Will retry registration in
18.258405ms if necessary
3: I1212 03:00:39.372346 18414 master.cpp:6077] Received register agent message
from slave(102)@172.17.0.5:43260 (e57dc9d7dd39)
3: I1212 03:00:39.372385 18414 master.cpp:3866] Authorizing agent with
principal 'test-principal'
3: I1212 03:00:39.372781 18428 master.cpp:6147] Authorized registration of
agent at slave(102)@172.17.0.5:43260 (e57dc9d7dd39)
3: I1212 03:00:39.372865 18428 master.cpp:6240] Registering agent at
slave(102)@172.17.0.5:43260 (e57dc9d7dd39) with id
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0
3: I1212 03:00:39.373448 18427 registrar.cpp:495] Applied 1 operations in
139206ns; attempting to update the registry
3: I1212 03:00:39.374104 18427 registrar.cpp:552] Successfully updated the
registry in 583936ns
3: I1212 03:00:39.374370 18425 master.cpp:6288] Admitted agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.375442 18425 master.cpp:6337] Registered agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I1212 03:00:39.375651 18419 slave.cpp:1253] Registered with master
master@172.17.0.5:43260; given agent ID 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0
3: I1212 03:00:39.375856 18431 task_status_update_manager.cpp:188] Resuming
sending task status updates
3: I1212 03:00:39.375844 18423 hierarchical.cpp:574] Added agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 (e57dc9d7dd39) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: {})
3: I1212 03:00:39.376184 18419 slave.cpp:1273] Checkpointing SlaveInfo to
'/tmp/MasterSlaveReconciliationTest_ReconcileDroppedTask_Nox5Q3/meta/slaves/60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0/slave.info'
3: I1212 03:00:39.376974 18419 slave.cpp:1330] Forwarding agent update
{"offer_operations":{},"resource_categories":{"oversubscribed":true},"resource_version_uuid":"UNx0PbkdSOenNQLr7Fub8A==","slave_id":{"value":"60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0"}}
3: I1212 03:00:39.377205 18423 hierarchical.cpp:1517] Performed allocation for
1 agents in 1.17304ms
3: I1212 03:00:39.377645 18430 master.cpp:8718] Sending 1 offers to framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (default) at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.377872 18430 master.cpp:7238] Received update of agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) with total oversubscribed resources {}
3: I1212 03:00:39.378063 18430 master.cpp:7336] Ignoring update on agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) as it reports no changes
3: I1212 03:00:39.378152 18420 sched.cpp:921] Scheduler::resourceOffers took
129929ns
3: I1212 03:00:39.379873 18422 master.cpp:10638] Removing offer
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-O0
3: I1212 03:00:39.380023 18422 master.cpp:4273] Processing ACCEPT call for
offers: [ 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-O0 ] on agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) for framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
(default) at scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.380123 18422 master.cpp:3593] Authorizing framework principal
'test-principal' to launch task 1
3: W1212 03:00:39.382694 18413 validation.cpp:1387] Executor 'default' for task
'1' uses less CPUs (None) than the minimum required (0.01). Please update your
executor, as this will be mandatory in future releases.
3: W1212 03:00:39.382745 18413 validation.cpp:1399] Executor 'default' for task
'1' uses less memory (None) than the minimum required (32MB). Please update
your executor, as this will be mandatory in future releases.
3: I1212 03:00:39.383587 18413 master.cpp:11393] Adding task 1 with resources
cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024;
ports(allocated: *):[31000-32000] on agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.384142 18413 master.cpp:5024] Launching task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (default) at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
on agent 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at
slave(102)@172.17.0.5:43260 (e57dc9d7dd39)
3: I1212 03:00:39.386409 18419 slave.cpp:1033] New master detected at
master@172.17.0.5:43260
3: I1212 03:00:39.386416 18423 task_status_update_manager.cpp:181] Pausing
sending task status updates
3: I1212 03:00:39.386495 18419 slave.cpp:1088] Detecting new master
3: I1212 03:00:39.395675 18412 slave.cpp:1115] Authenticating with master
master@172.17.0.5:43260
3: I1212 03:00:39.395728 18412 slave.cpp:1124] Using default CRAM-MD5
authenticatee
3: I1212 03:00:39.395946 18420 authenticatee.cpp:121] Creating new client SASL
connection
3: I1212 03:00:39.396240 18432 master.cpp:8888] Authenticating
slave(102)@172.17.0.5:43260
3: I1212 03:00:39.396347 18416 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(212)@172.17.0.5:43260
3: I1212 03:00:39.396580 18417 authenticator.cpp:98] Creating new server SASL
connection
3: I1212 03:00:39.396827 18435 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
3: I1212 03:00:39.396854 18435 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
3: I1212 03:00:39.396965 18435 authenticator.cpp:204] Received SASL
authentication start
3: I1212 03:00:39.397016 18435 authenticator.cpp:326] Authentication requires
more steps
3: I1212 03:00:39.397112 18435 authenticatee.cpp:259] Received SASL
authentication step
3: I1212 03:00:39.397222 18428 authenticator.cpp:232] Received SASL
authentication step
3: I1212 03:00:39.397246 18428 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'e57dc9d7dd39' server FQDN: 'e57dc9d7dd39'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
3: I1212 03:00:39.397258 18428 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
3: I1212 03:00:39.397279 18428 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
3: I1212 03:00:39.397298 18428 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'e57dc9d7dd39' server FQDN: 'e57dc9d7dd39'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
3: I1212 03:00:39.397308 18428 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1212 03:00:39.397313 18428 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1212 03:00:39.397325 18428 authenticator.cpp:318] Authentication success
3: I1212 03:00:39.397423 18422 authenticatee.cpp:299] Authentication success
3: I1212 03:00:39.397495 18428 master.cpp:8918] Successfully authenticated
principal 'test-principal' at slave(102)@172.17.0.5:43260
3: I1212 03:00:39.397567 18433 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(212)@172.17.0.5:43260
3: I1212 03:00:39.397851 18422 slave.cpp:1207] Successfully authenticated with
master master@172.17.0.5:43260
3: I1212 03:00:39.398138 18422 slave.cpp:1684] Will retry registration in
13.067633ms if necessary
3: I1212 03:00:39.398317 18421 master.cpp:6416] Received re-register agent
message from agent 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at
slave(102)@172.17.0.5:43260 (e57dc9d7dd39)
3: I1212 03:00:39.398373 18421 master.cpp:3866] Authorizing agent with
principal 'test-principal'
3: I1212 03:00:39.398713 18415 master.cpp:6505] Authorized re-registration of
agent 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.398783 18415 master.cpp:6571] Agent is already marked as
registered: 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at
slave(102)@172.17.0.5:43260 (e57dc9d7dd39)
3: I1212 03:00:39.398998 18415 master.cpp:6916] Registry updated for slave
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at
slave(102)@172.17.0.5:43260(e57dc9d7dd39)
3: W1212 03:00:39.399479 18415 master.cpp:8981] Task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 unknown to the agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) during re-registration: reconciling with the agent
3: I1212 03:00:39.399669 18431 hierarchical.cpp:669] Agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 (e57dc9d7dd39) updated with total
resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: W1212 03:00:39.399721 18415 master.cpp:9048] Executor 'default' of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 possibly unknown to the agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.399806 18415 master.cpp:10249] Removing executor 'default'
with resources [] of framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 on
agent 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.400054 18415 master.cpp:7077] Sending updated checkpointed
resources {} to agent 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at
slave(102)@172.17.0.5:43260 (e57dc9d7dd39)
3: I1212 03:00:39.400081 18425 slave.cpp:1366] Re-registered with master
master@172.17.0.5:43260
3: I1212 03:00:39.400177 18415 task_status_update_manager.cpp:188] Resuming
sending task status updates
3: I1212 03:00:39.400254 18425 slave.cpp:1411] Forwarding agent update
{"offer_operations":{},"resource_categories":{"oversubscribed":true},"resource_version_uuid":"UNx0PbkdSOenNQLr7Fub8A==","slave_id":{"value":"60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0"}}
3: W1212 03:00:39.400405 18425 slave.cpp:1451] Agent reconciling task 1 of
framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 in state TASK_DROPPED: task
unknown to the agent
3: I1212 03:00:39.400511 18426 master.cpp:7238] Received update of agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) with total oversubscribed resources {}
3: I1212 03:00:39.400591 18435 task_status_update_manager.cpp:328] Received
task status update TASK_DROPPED (Status UUID:
840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.400652 18435 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.400686 18425 slave.cpp:3624] Ignoring new checkpointed
resources identical to the current version: {}
3: I1212 03:00:39.400732 18426 master.cpp:7336] Ignoring update on agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) as it reports no changes
3: I1212 03:00:39.401068 18435 task_status_update_manager.cpp:383] Forwarding
task status update TASK_DROPPED (Status UUID:
840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 to the agent
3: I1212 03:00:39.401239 18424 slave.cpp:5215] Forwarding the update
TASK_DROPPED (Status UUID: 840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of
framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 to master@172.17.0.5:43260
3: I1212 03:00:39.401631 18424 slave.cpp:5108] Task status update manager
successfully handled status update TASK_DROPPED (Status UUID:
840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.401752 18413 master.cpp:7811] Status update TASK_DROPPED
(Status UUID: 840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 from agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.401805 18413 master.cpp:7867] Forwarding status update
TASK_DROPPED (Status UUID: 840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of
framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.402011 18413 master.cpp:10114] Updating the state of task 1
of framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (latest state:
TASK_DROPPED, status update state: TASK_DROPPED)
3: I1212 03:00:39.402331 18433 sched.cpp:1029] Scheduler::statusUpdate took
101537ns
3: I1212 03:00:39.402993 18413 master.cpp:5842] Processing ACKNOWLEDGE call
840fec46-021d-4244-adaa-d3277ef1bb87 for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (default) at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260 on agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0
3: I1212 03:00:39.403116 18434 hierarchical.cpp:1192] Recovered cpus(allocated:
*):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: {}) on agent 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 from framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.403132 18413 master.cpp:10220] Removing task 1 with resources
cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024;
ports(allocated: *):[31000-32000] of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 on agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.403697 18432 task_status_update_manager.cpp:401] Received
task status update acknowledgement (UUID: 840fec46-021d-4244-adaa-d3277ef1bb87)
for task 1 of framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.403780 18432 task_status_update_manager.cpp:538] Cleaning up
status update stream for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.404073 18412 slave.cpp:4010] Task status update manager
successfully handled status update acknowledgement (UUID:
840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: E1212 03:00:39.404096 18412 slave.cpp:4021] Status update acknowledgement
(UUID: 840fec46-021d-4244-adaa-d3277ef1bb87) for task 1 of unknown framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.406795 18435 process.cpp:3503] Handling HTTP event for
process 'metrics' with path: '/metrics/snapshot'
3: I1212 03:00:39.407882 18424 http.cpp:851] Authorizing principal 'ANY' to GET
the endpoint '/metrics/snapshot'
3: I1212 03:00:39.428273 18411 sched.cpp:2009] Asked to stop the driver
3: I1212 03:00:39.428438 18420 sched.cpp:1191] Stopping framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.428721 18434 master.cpp:9398] Processing TEARDOWN call for
framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (default) at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.428764 18434 master.cpp:9410] Removing framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (default) at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.428784 18434 master.cpp:3327] Deactivating framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 (default) at
scheduler-533efe4e-b19a-4d60-a505-bbab92695b6d@172.17.0.5:43260
3: I1212 03:00:39.428948 18416 hierarchical.cpp:405] Deactivated framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.429040 18419 slave.cpp:3375] Asked to shut down framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000 by master@172.17.0.5:43260
3: I1212 03:00:39.429083 18419 slave.cpp:3390] Cannot shut down unknown
framework 60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.429308 18412 hierarchical.cpp:344] Removed framework
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-0000
3: I1212 03:00:39.429749 18411 slave.cpp:909] Agent terminating
3: I1212 03:00:39.430124 18423 master.cpp:1305] Agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39) disconnected
3: I1212 03:00:39.430148 18423 master.cpp:3364] Disconnecting agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.430194 18423 master.cpp:3383] Deactivating agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 at slave(102)@172.17.0.5:43260
(e57dc9d7dd39)
3: I1212 03:00:39.430266 18435 hierarchical.cpp:766] Agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0 deactivated
3: I1212 03:00:39.438271 18411 master.cpp:1147] Master terminating
3: I1212 03:00:39.438901 18433 hierarchical.cpp:609] Removed agent
60a61de7-8db6-4cff-9e6d-f1fea1a6d9ef-S0
3: [ OK ] MasterSlaveReconciliationTest.ReconcileDroppedTask (116 ms)
3: [ RUN ] MasterSlaveReconciliationTest.ReconcileRace
3: I1212 03:00:39.448508 18411 cluster.cpp:172] Creating default 'local'
authorizer
3: I1212 03:00:39.453688 18425 master.cpp:456] Master
e12a57ba-cddb-4842-a55f-dcbe063bcc0d (e57dc9d7dd39) started on 172.17.0.5:43260
3: I1212 03:00:39.453754 18425 master.cpp:458] 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/3pAGVL/credentials"
--filter_gpu_resources="true" --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"
--max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--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="/usr/local/share/mesos/webui" --work_dir="/tmp/3pAGVL/master"
--zk_session_timeout="10secs"
3: I1212 03:00:39.454167 18425 master.cpp:507] Master only allowing
authenticated frameworks to register
3: I1212 03:00:39.454180 18425 master.cpp:513] Master only allowing
authenticated agents to register
3: I1212 03:00:39.454187 18425 master.cpp:519] Master only allowing
authenticated HTTP frameworks to register
3: I1212 03:00:39.454195 18425 credentials.hpp:37] Loading credentials for
authentication from '/tmp/3pAGVL/credentials'
3: I1212 03:00:39.454627 18425 master.cpp:563] Using default 'crammd5'
authenticator
3: I1212 03:00:39.454865 18425 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
3: I1212 03:00:39.455129 18425 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
3: I1212 03:00:39.455386 18425 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
3: I1212 03:00:39.455554 18425 master.cpp:642] Authorization enabled
3: I1212 03:00:39.455821 18420 whitelist_watcher.cpp:77] No whitelist given
3: I1212 03:00:39.455842 18423 hierarchical.cpp:175] Initialized hierarchical
allocator process
3: I1212 03:00:39.459919 18417 master.cpp:2209] Elected as the leading master!
3: I1212 03:00:39.459957 18417 master.cpp:1689] Recovering from registrar
3: I1212 03:00:39.460173 18413 registrar.cpp:347] Recovering registrar
3: I1212 03:00:39.460950 18413 registrar.cpp:391] Successfully fetched the
registry (0B) in 737792ns
3: I1212 03:00:39.461079 18413 registrar.cpp:495] Applied 1 operations in
45586ns; attempting to update the registry
3: I1212 03:00:39.461738 18413 registrar.cpp:552] Successfully updated the
registry in 596992ns
3: I1212 03:00:39.461884 18413 registrar.cpp:424] Successfully recovered
registrar
3: I1212 03:00:39.462424 18428 master.cpp:1802] Recovered 0 agents from the
registry (135B); allowing 10mins for agents to re-register
3: I1212 03:00:39.462505 18431 hierarchical.cpp:213] Skipping recovery of
hierarchical allocator: nothing to recover
3: W1212 03:00:39.469956 18411 process.cpp:2756] Attempted to spawn already
running process files@172.17.0.5:43260
3: I1212 03:00:39.470469 18411 cluster.cpp:460] Creating default 'local'
authorizer
3: I1212 03:00:39.474097 18412 slave.cpp:258] Mesos agent started on
(103)@172.17.0.5:43260
write /dev/stdout: resource temporarily unavailable
+ docker rmi mesos-1513045930-4451
Error response from daemon: conflict: unable to remove repository reference
"mesos-1513045930-4451" (must force) - container e57dc9d7dd39 is using its
referenced image 244a3e346b0e
Build step 'Execute shell' marked build as failure
Not sending mail to unregistered user gregorywm...@gmail.com
Not sending mail to unregistered user yujie....@gmail.com
