See
<https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4486/display/redirect?page=changes>
Changes:
[alexr] Fixed a task status update race in default executor tests.
[alexr] Renamed `TaskStatusEq()` to `TaskStatusTaskIdEq()`.
------------------------------------------
[...truncated 21.35 MB...]
3: I1121 18:33:52.202800 17520 whitelist_watcher.cpp:77] No whitelist given
3: I1121 18:33:52.205539 17532 master.cpp:2215] Elected as the leading master!
3: I1121 18:33:52.205579 17532 master.cpp:1695] Recovering from registrar
3: I1121 18:33:52.205708 17521 registrar.cpp:347] Recovering registrar
3: I1121 18:33:52.206277 17521 registrar.cpp:391] Successfully fetched the
registry (0B) in 532992ns
3: I1121 18:33:52.206392 17521 registrar.cpp:495] Applied 1 operations in
33847ns; attempting to update the registry
3: I1121 18:33:52.206905 17521 registrar.cpp:552] Successfully updated the
registry in 459008ns
3: I1121 18:33:52.207023 17521 registrar.cpp:424] Successfully recovered
registrar
3: I1121 18:33:52.207393 17520 master.cpp:1808] Recovered 0 agents from the
registry (129B); allowing 10mins for agents to re-register
3: I1121 18:33:52.207430 17532 hierarchical.cpp:211] Skipping recovery of
hierarchical allocator: nothing to recover
3: I1121 18:33:52.210367 17517 containerizer.cpp:301] Using isolation {
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1121 18:33:52.210835 17517 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges
3: W1121 18:33:52.210988 17517 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
3: I1121 18:33:52.211057 17517 provisioner.cpp:259] Using default backend 'copy'
3: W1121 18:33:52.214975 17517 process.cpp:2756] Attempted to spawn already
running process [email protected]:55533
3: I1121 18:33:52.215270 17517 cluster.cpp:448] Creating default 'local'
authorizer
3: I1121 18:33:52.217933 17533 slave.cpp:262] Mesos agent started on
(543)@172.17.0.3:55533
3: I1121 18:33:52.217964 17533 slave.cpp:263] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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_secret_key="/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/executor_secret_key"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --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" --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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln"
--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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh"
--zk_session_timeout="10secs"
3: I1121 18:33:52.218658 17533 credentials.hpp:86] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/credential'
3: W1121 18:33:52.218778 17517 process.cpp:2756] Attempted to spawn already
running process [email protected]:55533
3: I1121 18:33:52.218864 17533 slave.cpp:295] Agent using credential for:
test-principal
3: I1121 18:33:52.218881 17533 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/http_credentials'
3: I1121 18:33:52.219434 17533 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
3: I1121 18:33:52.219588 17533 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
3: I1121 18:33:52.219668 17517 sched.cpp:232] Version: 1.5.0
3: I1121 18:33:52.219857 17533 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
3: I1121 18:33:52.219966 17533 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
3: I1121 18:33:52.220178 17533 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
3: I1121 18:33:52.220281 17533 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
3: I1121 18:33:52.220343 17530 sched.cpp:336] New master detected at
[email protected]:55533
3: I1121 18:33:52.220432 17530 sched.cpp:396] Authenticating with master
[email protected]:55533
3: I1121 18:33:52.220466 17530 sched.cpp:403] Using default CRAM-MD5
authenticatee
3: I1121 18:33:52.220805 17531 authenticatee.cpp:121] Creating new client SASL
connection
3: I1121 18:33:52.221254 17522 master.cpp:8306] Authenticating
[email protected]:55533
3: I1121 18:33:52.221483 17522 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1094)@172.17.0.3:55533
3: I1121 18:33:52.221935 17522 authenticator.cpp:98] Creating new server SASL
connection
3: I1121 18:33:52.222146 17523 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
3: I1121 18:33:52.222169 17523 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
3: I1121 18:33:52.222301 17528 authenticator.cpp:204] Received SASL
authentication start
3: I1121 18:33:52.222359 17528 authenticator.cpp:326] Authentication requires
more steps
3: I1121 18:33:52.222136 17533 slave.cpp:593] 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: I1121 18:33:52.222396 17533 slave.cpp:601] Agent attributes: [ ]
3: I1121 18:33:52.222409 17533 slave.cpp:610] Agent hostname: 48f3070c3da3
3: I1121 18:33:52.222476 17528 authenticatee.cpp:259] Received SASL
authentication step
3: I1121 18:33:52.222566 17527 task_status_update_manager.cpp:181] Pausing
sending task status updates
3: I1121 18:33:52.222601 17528 authenticator.cpp:232] Received SASL
authentication step
3: I1121 18:33:52.222628 17528 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: '48f3070c3da3' server FQDN: '48f3070c3da3'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
3: I1121 18:33:52.222647 17528 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
3: I1121 18:33:52.222694 17528 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
3: I1121 18:33:52.222728 17528 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: '48f3070c3da3' server FQDN: '48f3070c3da3'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
3: I1121 18:33:52.222740 17528 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1121 18:33:52.222748 17528 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1121 18:33:52.222764 17528 authenticator.cpp:318] Authentication success
3: I1121 18:33:52.222882 17518 authenticatee.cpp:299] Authentication success
3: I1121 18:33:52.222915 17530 master.cpp:8336] Successfully authenticated
principal 'test-principal' at
[email protected]:55533
3: I1121 18:33:52.223012 17519 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1094)@172.17.0.3:55533
3: I1121 18:33:52.223253 17531 sched.cpp:502] Successfully authenticated with
master [email protected]:55533
3: I1121 18:33:52.223273 17531 sched.cpp:824] Sending SUBSCRIBE call to
[email protected]:55533
3: I1121 18:33:52.223403 17531 sched.cpp:857] Will retry registration in
745.495021ms if necessary
3: I1121 18:33:52.223600 17524 master.cpp:2963] Received SUBSCRIBE call for
framework 'default' at
[email protected]:55533
3: I1121 18:33:52.223692 17524 master.cpp:2280] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
3: I1121 18:33:52.224194 17520 master.cpp:3043] Subscribing framework default
with checkpointing enabled and capabilities [ RESERVATION_REFINEMENT ]
3: I1121 18:33:52.224370 17525 state.cpp:64] Recovering state from
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta'
3: I1121 18:33:52.224738 17521 task_status_update_manager.cpp:207] Recovering
task status update manager
3: I1121 18:33:52.224967 17522 sched.cpp:751] Framework registered with
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.225016 17519 containerizer.cpp:668] Recovering containerizer
3: I1121 18:33:52.225033 17522 sched.cpp:765] Scheduler::registered took 42042ns
3: I1121 18:33:52.225317 17518 hierarchical.cpp:306] Added framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.225525 17518 hierarchical.cpp:1457] Performed allocation for
0 agents in 78328ns
3: I1121 18:33:52.226544 17522 provisioner.cpp:455] Provisioner recovery
complete
3: I1121 18:33:52.226883 17527 slave.cpp:6443] Finished recovery
3: I1121 18:33:52.227653 17533 task_status_update_manager.cpp:181] Pausing
sending task status updates
3: I1121 18:33:52.227664 17528 slave.cpp:1007] New master detected at
[email protected]:55533
3: I1121 18:33:52.227780 17528 slave.cpp:1042] Detecting new master
3: I1121 18:33:52.234069 17521 slave.cpp:1069] Authenticating with master
[email protected]:55533
3: I1121 18:33:52.234139 17521 slave.cpp:1078] Using default CRAM-MD5
authenticatee
3: I1121 18:33:52.234400 17525 authenticatee.cpp:121] Creating new client SASL
connection
3: I1121 18:33:52.234735 17519 master.cpp:8306] Authenticating
slave(543)@172.17.0.3:55533
3: I1121 18:33:52.234891 17531 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1095)@172.17.0.3:55533
3: I1121 18:33:52.235170 17523 authenticator.cpp:98] Creating new server SASL
connection
3: I1121 18:33:52.235414 17530 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
3: I1121 18:33:52.235441 17530 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
3: I1121 18:33:52.235551 17520 authenticator.cpp:204] Received SASL
authentication start
3: I1121 18:33:52.235606 17520 authenticator.cpp:326] Authentication requires
more steps
3: I1121 18:33:52.235715 17520 authenticatee.cpp:259] Received SASL
authentication step
3: I1121 18:33:52.235857 17522 authenticator.cpp:232] Received SASL
authentication step
3: I1121 18:33:52.235888 17522 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: '48f3070c3da3' server FQDN: '48f3070c3da3'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
3: I1121 18:33:52.235908 17522 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
3: I1121 18:33:52.235949 17522 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
3: I1121 18:33:52.235976 17522 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: '48f3070c3da3' server FQDN: '48f3070c3da3'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
3: I1121 18:33:52.235988 17522 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1121 18:33:52.235993 17522 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1121 18:33:52.236004 17522 authenticator.cpp:318] Authentication success
3: I1121 18:33:52.236116 17526 authenticatee.cpp:299] Authentication success
3: I1121 18:33:52.236150 17527 master.cpp:8336] Successfully authenticated
principal 'test-principal' at slave(543)@172.17.0.3:55533
3: I1121 18:33:52.236215 17522 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1095)@172.17.0.3:55533
3: I1121 18:33:52.236454 17518 slave.cpp:1161] Successfully authenticated with
master [email protected]:55533
3: I1121 18:33:52.236711 17518 slave.cpp:1682] Will retry registration in
7.74671ms if necessary
3: I1121 18:33:52.236954 17521 master.cpp:6036] Received register agent message
from slave(543)@172.17.0.3:55533 (48f3070c3da3)
3: I1121 18:33:52.237087 17521 master.cpp:3872] Authorizing agent with
principal 'test-principal'
3: I1121 18:33:52.237570 17519 master.cpp:6098] Authorized registration of
agent at slave(543)@172.17.0.3:55533 (48f3070c3da3)
3: I1121 18:33:52.237702 17519 master.cpp:6191] Registering agent at
slave(543)@172.17.0.3:55533 (48f3070c3da3) with id
81297555-36c1-4443-b004-599fca0d0ea4-S0
3: I1121 18:33:52.238138 17531 registrar.cpp:495] Applied 1 operations in
64036ns; attempting to update the registry
3: I1121 18:33:52.238765 17531 registrar.cpp:552] Successfully updated the
registry in 563200ns
3: I1121 18:33:52.238957 17527 master.cpp:6240] Admitted agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3)
3: I1121 18:33:52.239771 17532 slave.cpp:1207] Registered with master
[email protected]:55533; given agent ID 81297555-36c1-4443-b004-599fca0d0ea4-S0
3: I1121 18:33:52.239619 17527 master.cpp:6273] Registered agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3) with
[{"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: I1121 18:33:52.239910 17522 task_status_update_manager.cpp:188] Resuming
sending task status updates
3: I1121 18:33:52.240094 17526 hierarchical.cpp:600] Added agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 (48f3070c3da3) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: {})
3: I1121 18:33:52.240186 17532 slave.cpp:1227] Checkpointing SlaveInfo to
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/slave.info'
3: I1121 18:33:52.240619 17532 slave.cpp:1295] Forwarding total oversubscribed
resources {}
3: I1121 18:33:52.240823 17532 master.cpp:7085] Received update of agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3) with total oversubscribed resources {}
3: I1121 18:33:52.241027 17532 master.cpp:7103] Ignoring update on agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3) as it reports no changes
3: I1121 18:33:52.241345 17526 hierarchical.cpp:1457] Performed allocation for
1 agents in 1.063451ms
3: I1121 18:33:52.241817 17518 master.cpp:8136] Sending 1 offers to framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 (default) at
[email protected]:55533
3: I1121 18:33:52.242295 17521 sched.cpp:921] Scheduler::resourceOffers took
90976ns
3: I1121 18:33:52.244472 17524 master.cpp:10045] Removing offer
81297555-36c1-4443-b004-599fca0d0ea4-O0
3: I1121 18:33:52.244643 17524 master.cpp:4230] Processing ACCEPT call for
offers: [ 81297555-36c1-4443-b004-599fca0d0ea4-O0 ] on agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3) for framework 81297555-36c1-4443-b004-599fca0d0ea4-0000
(default) at [email protected]:55533
3: I1121 18:33:52.244776 17524 master.cpp:3599] Authorizing framework principal
'test-principal' to launch task 998a4d99-500f-4eeb-b311-39dc559dc211
3: I1121 18:33:52.246845 17522 master.cpp:10793] Adding task
998a4d99-500f-4eeb-b311-39dc559dc211 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 81297555-36c1-4443-b004-599fca0d0ea4-S0 at
slave(543)@172.17.0.3:55533 (48f3070c3da3)
3: I1121 18:33:52.247478 17522 master.cpp:4978] Launching task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 (default) at
[email protected]:55533 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 81297555-36c1-4443-b004-599fca0d0ea4-S0 at
slave(543)@172.17.0.3:55533 (48f3070c3da3)
3: I1121 18:33:52.248334 17532 slave.cpp:1803] Got assigned task
'998a4d99-500f-4eeb-b311-39dc559dc211' for framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.248495 17532 slave.cpp:7657] Checkpointing FrameworkInfo to
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/framework.info'
3: I1121 18:33:52.248867 17532 slave.cpp:7668] Checkpointing framework pid
'[email protected]:55533' to
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/framework.pid'
3: I1121 18:33:52.249580 17532 slave.cpp:2071] Authorizing task
'998a4d99-500f-4eeb-b311-39dc559dc211' for framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.249635 17532 slave.cpp:7264] Authorizing framework principal
'test-principal' to launch task 998a4d99-500f-4eeb-b311-39dc559dc211
3: I1121 18:33:52.250399 17519 slave.cpp:2239] Launching task
'998a4d99-500f-4eeb-b311-39dc559dc211' for framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.251068 17519 paths.cpp:621] Trying to chown
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f'
to user 'mesos'
3: I1121 18:33:52.251363 17519 slave.cpp:8362] Checkpointing ExecutorInfo to
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/executor.info'
3: I1121 18:33:52.252063 17519 slave.cpp:7738] Launching executor
'998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}]
in work directory
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f'
3: I1121 18:33:52.253068 17519 slave.cpp:8405] Checkpointing TaskInfo to
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f/tasks/998a4d99-500f-4eeb-b311-39dc559dc211/task.info'
3: I1121 18:33:52.253597 17519 slave.cpp:2467] Queued task
'998a4d99-500f-4eeb-b311-39dc559dc211' for executor
'998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.253711 17519 slave.cpp:958] Successfully attached
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f'
to virtual path
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/latest'
3: I1121 18:33:52.253782 17519 slave.cpp:958] Successfully attached
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f'
to virtual path
'/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/latest'
3: I1121 18:33:52.253830 17519 slave.cpp:958] Successfully attached
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f'
to virtual path
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f'
3: I1121 18:33:52.254205 17519 slave.cpp:2930] Launching container
104b542c-86f3-4c80-b2f5-385df292d31f for executor
'998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.254489 17523 containerizer.cpp:1195] Starting container
104b542c-86f3-4c80-b2f5-385df292d31f
3: I1121 18:33:52.255249 17523 containerizer.cpp:1367] Checkpointed
ContainerConfig at
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/containers/104b542c-86f3-4c80-b2f5-385df292d31f/config'
3: I1121 18:33:52.255272 17523 containerizer.cpp:2919] Transitioning the state
of container 104b542c-86f3-4c80-b2f5-385df292d31f from PROVISIONING to PREPARING
3: I1121 18:33:52.259171 17518 containerizer.cpp:1836] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/build\/src"],"shell":false,"value":"\/mesos\/build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.3:55533"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh\/slaves\/81297555-36c1-4443-b004-599fca0d0ea4-S0\/frameworks\/81297555-36c1-4443-b004-599fca0d0ea4-0000\/executors\/998a4d99-500f-4eeb-b311-39dc559dc211\/runs\/104b542c-86f3-4c80-b2f5-385df292d31f"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIxMDRiNTQyYy04NmYzLTRjODAtYjJmNS0zODVkZjI5MmQzMWYiLCJlaWQiOiI5OThhNGQ5OS01MDBmLTRlZWItYjMxMS0zOWRjNTU5ZGMyMTEiLCJmaWQiOiI4MTI5NzU1NS0zNmMxLTQ0NDMtYjAwNC01OTlmY2EwZDBlYTQtMDAwMCJ9.ZsIH3Rvu8wVRIVL2sQo8sYwamiAlynufrjs-jVbfBpI"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"998a4d99-500f-4eeb-b311-39dc559dc211"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"81297555-36c1-4443-b004-599fca0d0ea4-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_RECOVERY_TIMEOUT","type":"VALUE","value":"15mins"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"81297555-36c1-4443-b004-599fca0d0ea4-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(543)@172.17.0.3:55533"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh\/slaves\/81297555-36c1-4443-b004-599fca0d0ea4-S0\/frameworks\/81297555-36c1-4443-b004-599fca0d0ea4-0000\/executors\/998a4d99-500f-4eeb-b311-39dc559dc211\/runs\/104b542c-86f3-4c80-b2f5-385df292d31f"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh\/slaves\/81297555-36c1-4443-b004-599fca0d0ea4-S0\/frameworks\/81297555-36c1-4443-b004-599fca0d0ea4-0000\/executors\/998a4d99-500f-4eeb-b311-39dc559dc211\/runs\/104b542c-86f3-4c80-b2f5-385df292d31f"}"
--pipe_read="8" --pipe_write="9"
--runtime_directory="/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/containers/104b542c-86f3-4c80-b2f5-385df292d31f"
--unshare_namespace_mnt="false"'
3: I1121 18:33:52.261180 17518 launcher.cpp:140] Forked child with pid '21465'
for container '104b542c-86f3-4c80-b2f5-385df292d31f'
3: I1121 18:33:52.261309 17518 containerizer.cpp:1928] Checkpointing
container's forked pid 21465 to
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f/pids/forked.pid'
3: I1121 18:33:52.262168 17518 containerizer.cpp:2919] Transitioning the state
of container 104b542c-86f3-4c80-b2f5-385df292d31f from PREPARING to ISOLATING
3: I1121 18:33:52.263403 17518 containerizer.cpp:2919] Transitioning the state
of container 104b542c-86f3-4c80-b2f5-385df292d31f from ISOLATING to FETCHING
3: I1121 18:33:52.263578 17526 fetcher.cpp:379] Starting to fetch URIs for
container: 104b542c-86f3-4c80-b2f5-385df292d31f, directory:
/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f
3: I1121 18:33:52.264411 17525 containerizer.cpp:2919] Transitioning the state
of container 104b542c-86f3-4c80-b2f5-385df292d31f from FETCHING to RUNNING
3: I1121 18:33:52.489982 21478 exec.cpp:162] Version: 1.5.0
3: I1121 18:33:52.498991 17521 slave.cpp:4063] Got registration for executor
'998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 from executor(1)@172.17.0.3:36588
3: I1121 18:33:52.499536 17521 slave.cpp:4149] Checkpointing executor pid
'executor(1)@172.17.0.3:36588' to
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/slaves/81297555-36c1-4443-b004-599fca0d0ea4-S0/frameworks/81297555-36c1-4443-b004-599fca0d0ea4-0000/executors/998a4d99-500f-4eeb-b311-39dc559dc211/runs/104b542c-86f3-4c80-b2f5-385df292d31f/pids/libprocess.pid'
3: I1121 18:33:52.502143 17533 slave.cpp:2669] Sending queued task
'998a4d99-500f-4eeb-b311-39dc559dc211' to executor
'998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 at executor(1)@172.17.0.3:36588
3: I1121 18:33:52.505239 21470 exec.cpp:237] Executor registered on agent
81297555-36c1-4443-b004-599fca0d0ea4-S0
3: I1121 18:33:52.508815 21472 executor.cpp:171] Received SUBSCRIBED event
3: I1121 18:33:52.509902 21472 executor.cpp:175] Subscribed executor on
48f3070c3da3
3: I1121 18:33:52.510080 21472 executor.cpp:171] Received LAUNCH event
3: I1121 18:33:52.511906 21472 executor.cpp:637] Starting task
998a4d99-500f-4eeb-b311-39dc559dc211
3: I1121 18:33:52.514940 17527 slave.cpp:4517] Handling status update
TASK_STARTING (UUID: 5ed4c465-18da-49ff-941f-e2cc691536b6) for task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 from executor(1)@172.17.0.3:36588
3: I1121 18:33:52.516814 17522 task_status_update_manager.cpp:328] Received
task status update TASK_STARTING (UUID: 5ed4c465-18da-49ff-941f-e2cc691536b6)
for task 998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.516870 17522 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.517649 17522 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_STARTING (UUID:
5ed4c465-18da-49ff-941f-e2cc691536b6) for task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.517915 17522 task_status_update_manager.cpp:383] Forwarding
task status update TASK_STARTING (UUID: 5ed4c465-18da-49ff-941f-e2cc691536b6)
for task 998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 to the agent
3: I1121 18:33:52.518189 17523 slave.cpp:5000] Forwarding the update
TASK_STARTING (UUID: 5ed4c465-18da-49ff-941f-e2cc691536b6) for task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 to [email protected]:55533
3: I1121 18:33:52.518767 17523 slave.cpp:4893] Task status update manager
successfully handled status update TASK_STARTING (UUID:
5ed4c465-18da-49ff-941f-e2cc691536b6) for task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.518823 17523 slave.cpp:4909] Sending acknowledgement for
status update TASK_STARTING (UUID: 5ed4c465-18da-49ff-941f-e2cc691536b6) for
task 998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 to executor(1)@172.17.0.3:36588
3: I1121 18:33:52.519093 17523 slave.cpp:883] Agent terminating
3: I1121 18:33:52.519376 17521 master.cpp:1311] Agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3) disconnected
3: I1121 18:33:52.519397 17521 master.cpp:3370] Disconnecting agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3)
3: I1121 18:33:52.519456 17521 master.cpp:3389] Deactivating agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(543)@172.17.0.3:55533
(48f3070c3da3)
3: I1121 18:33:52.519487 17517 containerizer.cpp:301] Using isolation {
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: I1121 18:33:52.519551 17525 hierarchical.cpp:697] Agent
81297555-36c1-4443-b004-599fca0d0ea4-S0 deactivated
3: W1121 18:33:52.520009 17517 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges
3: W1121 18:33:52.520138 17517 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
3: I1121 18:33:52.520165 17517 provisioner.cpp:259] Using default backend 'copy'
3: I1121 18:33:52.525882 21472 executor.cpp:477] Running
'/mesos/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
3: W1121 18:33:52.528297 17517 process.cpp:2756] Attempted to spawn already
running process [email protected]:55533
3: I1121 18:33:52.528445 21472 executor.cpp:650] Forked command at 21484
3: I1121 18:33:52.528934 17517 cluster.cpp:448] Creating default 'local'
authorizer
3: I1121 18:33:52.531296 17534 process.cpp:2578] Failed to deliver libprocess
message to /slave(543)/mesos.internal.StatusUpdateMessage
3: I1121 18:33:52.532418 17532 slave.cpp:262] Mesos agent started on
(544)@172.17.0.3:55533
3: I1121 18:33:52.532443 17532 slave.cpp:263] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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_secret_key="/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/executor_secret_key"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --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" --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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln"
--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/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh"
--zk_session_timeout="10secs"
3: I1121 18:33:52.533149 17532 credentials.hpp:86] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/credential'
3: I1121 18:33:52.533381 17532 slave.cpp:295] Agent using credential for:
test-principal
3: I1121 18:33:52.533398 17532 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_w3TWln/http_credentials'
3: I1121 18:33:52.533706 17532 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
3: I1121 18:33:52.533874 17532 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
3: I1121 18:33:52.537631 17532 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
3: I1121 18:33:52.537858 17532 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
3: I1121 18:33:52.538180 17532 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
3: I1121 18:33:52.538381 17532 http.cpp:1066] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
3: I1121 18:33:52.540710 17532 slave.cpp:593] 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: I1121 18:33:52.541056 17532 slave.cpp:601] Agent attributes: [ ]
3: I1121 18:33:52.541071 17532 slave.cpp:610] Agent hostname: 48f3070c3da3
3: I1121 18:33:52.541301 17521 task_status_update_manager.cpp:181] Pausing
sending task status updates
3: I1121 18:33:52.543561 17523 state.cpp:64] Recovering state from
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta'
3: I1121 18:33:52.543627 17523 state.cpp:722] No committed checkpointed
resources found at
'/tmp/SlaveRecoveryTest_0_RecoverTaskStatusUpdateManager_XnssWh/meta/resources/resources.info'
3: I1121 18:33:52.547140 17530 slave.cpp:6540] Recovering framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.547251 17530 slave.cpp:7852] Recovering executor
'998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.548079 17533 task_status_update_manager.cpp:207] Recovering
task status update manager
3: I1121 18:33:52.548102 17533 task_status_update_manager.cpp:215] Recovering
executor '998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.548158 17533 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.548696 17533 task_status_update_manager.cpp:818] Replaying
task status update stream for task 998a4d99-500f-4eeb-b311-39dc559dc211
3: I1121 18:33:52.549145 17522 containerizer.cpp:668] Recovering containerizer
3: I1121 18:33:52.549212 17522 containerizer.cpp:725] Recovering container
104b542c-86f3-4c80-b2f5-385df292d31f for executor
'998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.551834 17530 provisioner.cpp:455] Provisioner recovery
complete
3: I1121 18:33:52.552873 17521 slave.cpp:6327] Sending reconnect request to
executor '998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 at executor(1)@172.17.0.3:36588
3: I1121 18:33:52.555166 21468 exec.cpp:283] Received reconnect request from
agent 81297555-36c1-4443-b004-599fca0d0ea4-S0
3: I1121 18:33:52.557523 17523 slave.cpp:4227] Received re-registration message
from executor '998a4d99-500f-4eeb-b311-39dc559dc211' of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.557914 17523 slave.cpp:4517] Handling status update
TASK_RUNNING (UUID: 7d25887e-83a7-4d02-9af0-cb2f94fc5e00) for task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 from executor(1)@172.17.0.3:36588
3: I1121 18:33:52.559667 17521 task_status_update_manager.cpp:328] Received
task status update TASK_RUNNING (UUID: 7d25887e-83a7-4d02-9af0-cb2f94fc5e00)
for task 998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.559775 17521 task_status_update_manager.cpp:842]
Checkpointing UPDATE for task status update TASK_RUNNING (UUID:
7d25887e-83a7-4d02-9af0-cb2f94fc5e00) for task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.560204 17521 slave.cpp:4893] Task status update manager
successfully handled status update TASK_RUNNING (UUID:
7d25887e-83a7-4d02-9af0-cb2f94fc5e00) for task
998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000
3: I1121 18:33:52.560256 17521 slave.cpp:4909] Sending acknowledgement for
status update TASK_RUNNING (UUID: 7d25887e-83a7-4d02-9af0-cb2f94fc5e00) for
task 998a4d99-500f-4eeb-b311-39dc559dc211 of framework
81297555-36c1-4443-b004-599fca0d0ea4-0000 to executor(1)@172.17.0.3:36588
3: I1121 18:33:52.561226 21469 exec.cpp:260] Executor re-registered on agent
81297555-36c1-4443-b004-599fca0d0ea4-S0
3: I1121 18:33:52.563740 21473 executor.cpp:171] Received SUBSCRIBED event
3: I1121 18:33:52.563763 21473 executor.cpp:175] Subscribed executor on
48f3070c3da3
3: I1121 18:33:53.203964 17518 hierarchical.cpp:1457] Performed allocation for
1 agents in 195553ns
3: I1121 18:33:54.206286 17520 hierarchical.cpp:1457] Performed allocation for
1 agents in 192333ns
3: I1121 18:33:54.554278 17518 slave.cpp:4445] Cleaning up un-reregistered
executors
3: I1121 18:33:54.554440 17518 slave.cpp:6443] Finished recovery
3: I1121 18:33:54.555490 17518 task_status_update_manager.cpp:181] Pausing
sending task status updates
3: I1121 18:33:54.555619 17519 slave.cpp:1007] New master detected at
[email protected]:55533
3: I1121 18:33:54.555838 17519 slave.cpp:1042] Detecting new master
3: I1121 18:33:54.558362 17521 slave.cpp:1069] Authenticating with master
[email protected]:55533
3: I1121 18:33:54.558493 17521 slave.cpp:1078] Using default CRAM-MD5
authenticatee
3: I1121 18:33:54.558984 17521 authenticatee.cpp:121] Creating new client SASL
connection
3: I1121 18:33:54.559375 17532 master.cpp:8306] Authenticating
slave(544)@172.17.0.3:55533
3: I1121 18:33:54.559556 17522 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1096)@172.17.0.3:55533
3: I1121 18:33:54.559998 17522 authenticator.cpp:98] Creating new server SASL
connection
3: I1121 18:33:54.560276 17522 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
3: I1121 18:33:54.560299 17522 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
3: I1121 18:33:54.560422 17522 authenticator.cpp:204] Received SASL
authentication start
3: I1121 18:33:54.560479 17522 authenticator.cpp:326] Authentication requires
more steps
3: I1121 18:33:54.560618 17529 authenticatee.cpp:259] Received SASL
authentication step
3: I1121 18:33:54.560799 17530 authenticator.cpp:232] Received SASL
authentication step
3: I1121 18:33:54.560847 17530 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: '48f3070c3da3' server FQDN: '48f3070c3da3'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
3: I1121 18:33:54.560861 17530 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
3: I1121 18:33:54.560914 17530 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
3: I1121 18:33:54.560941 17530 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: '48f3070c3da3' server FQDN: '48f3070c3da3'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
3: I1121 18:33:54.560955 17530 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1121 18:33:54.560962 17530 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1121 18:33:54.560981 17530 authenticator.cpp:318] Authentication success
3: I1121 18:33:54.561086 17527 authenticatee.cpp:299] Authentication success
3: I1121 18:33:54.561758 17524 master.cpp:8336] Successfully authenticated
principal 'test-principal' at slave(544)@172.17.0.3:55533
3: I1121 18:33:54.561852 17519 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1096)@172.17.0.3:55533
3: I1121 18:33:54.562093 17527 slave.cpp:1161] Successfully authenticated with
master [email protected]:55533
3: I1121 18:33:54.562633 17527 slave.cpp:1682] Will retry registration in
17.347921ms if necessary
3: I1121 18:33:54.563297 17528 master.cpp:6362] Received re-register agent
message from agent 81297555-36c1-4443-b004-599fca0d0ea4-S0 at
slave(544)@172.17.0.3:55533 (48f3070c3da3)
3: I1121 18:33:54.563560 17528 master.cpp:3872] Authorizing agent with
principal 'test-principal'
3: I1121 18:33:54.564183 17522 master.cpp:6433] Authorized re-registration of
agent 81297555-36c1-4443-b004-599fca0d0ea4-S0 at slave(544)@172.17.0.3:55533
(48f3070c3da3)
Build step 'Execute shell' marked build as failure
