[MESOS-7741] SlaveRecoveryTest/0.MultipleSlaves has double free corruption - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.5.0
Component/s: None
Labels:
- flaky-test
- mesosphere-oncall

Description

Observed this on ASF CI

[ RUN      ] SlaveRecoveryTest/0.MultipleSlaves
I0629 05:34:49.170672  1262 cluster.cpp:162] Creating default 'local' authorizer
I0629 05:34:49.173851  1284 master.cpp:436] Master 00585c7a-2135-427f-8997-07274f586d94 (f194a3049b2b) started on 172.17.0.4:44620
I0629 05:34:49.173909  1284 master.cpp:438] 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" --au
thenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/tobw4y/credentials" --framework_sorter="drf" --help="false" --hostn
ame_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="10
00" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registr
y_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.3.1/_inst/share/mesos/webui" --work_dir="/tmp/tobw4y/master" --zk_session_timeout="10secs"
I0629 05:34:49.174388  1284 master.cpp:488] Master only allowing authenticated frameworks to register
I0629 05:34:49.174401  1284 master.cpp:502] Master only allowing authenticated agents to register
I0629 05:34:49.174409  1284 master.cpp:515] Master only allowing authenticated HTTP frameworks to register
I0629 05:34:49.174419  1284 credentials.hpp:37] Loading credentials for authentication from '/tmp/tobw4y/credentials'
I0629 05:34:49.174836  1284 master.cpp:560] Using default 'crammd5' authenticator
I0629 05:34:49.175052  1284 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0629 05:34:49.175221  1284 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0629 05:34:49.175312  1284 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0629 05:34:49.175395  1284 master.cpp:640] Authorization enabled
I0629 05:34:49.178370  1286 whitelist_watcher.cpp:77] No whitelist given
I0629 05:34:49.178886  1301 master.cpp:2161] Elected as the leading master!
I0629 05:34:49.178954  1301 master.cpp:1700] Recovering from registrar
I0629 05:34:49.179147  1293 registrar.cpp:345] Recovering registrar
I0629 05:34:49.179462  1294 hierarchical.cpp:158] Initialized hierarchical allocator process
I0629 05:34:49.181064  1293 registrar.cpp:389] Successfully fetched the registry (0B) in 1.782016ms
I0629 05:34:49.181200  1293 registrar.cpp:493] Applied 1 operations in 25873ns; attempting to update the registry
I0629 05:34:49.181843  1293 registrar.cpp:550] Successfully updated the registry in 561920ns
I0629 05:34:49.181963  1293 registrar.cpp:422] Successfully recovered registrar
I0629 05:34:49.182598  1293 master.cpp:1799] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
I0629 05:34:49.182875  1291 hierarchical.cpp:185] Skipping recovery of hierarchical allocator: nothing to recover
I0629 05:34:49.184635  1262 sched.cpp:232] Version: 1.3.1
I0629 05:34:49.185497  1292 sched.cpp:336] New master detected at master@172.17.0.4:44620
I0629 05:34:49.185989  1292 sched.cpp:407] Authenticating with master master@172.17.0.4:44620
I0629 05:34:49.186084  1292 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0629 05:34:49.186440  1296 authenticatee.cpp:121] Creating new client SASL connection
I0629 05:34:49.186724  1296 master.cpp:7475] Authenticating scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620
I0629 05:34:49.186830  1292 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(986)@172.17.0.4:44620
I0629 05:34:49.187090  1304 authenticator.cpp:98] Creating new server SASL connection
I0629 05:34:49.187446  1289 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0629 05:34:49.187643  1289 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0629 05:34:49.187865  1287 authenticator.cpp:204] Received SASL authentication start
I0629 05:34:49.187945  1287 authenticator.cpp:326] Authentication requires more steps
I0629 05:34:49.188048  1262 containerizer.cpp:221] Using isolation: filesystem/posix,posix/mem,posix/cpu,network/cni
I0629 05:34:49.188112  1281 authenticatee.cpp:259] Received SASL authentication step
I0629 05:34:49.188261  1281 authenticator.cpp:232] Received SASL authentication step
I0629 05:34:49.188320  1281 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f194a3049b2b' server FQDN: 'f194a3049b2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0629 05:34:49.188359  1281 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0629 05:34:49.188418  1281 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0629 05:34:49.188467  1281 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f194a3049b2b' server FQDN: 'f194a3049b2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0629 05:34:49.188504  1281 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 05:34:49.188534  1281 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 05:34:49.188571  1281 authenticator.cpp:318] Authentication success
I0629 05:34:49.188771  1281 authenticatee.cpp:299] Authentication success
I0629 05:34:49.188854  1287 master.cpp:7505] Successfully authenticated principal 'test-principal' at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620
I0629 05:34:49.188908  1281 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(986)@172.17.0.4:44620
W0629 05:34:49.188782  1262 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0629 05:34:49.189254  1262 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0629 05:34:49.189275  1291 sched.cpp:513] Successfully authenticated with master master@172.17.0.4:44620
I0629 05:34:49.189327  1262 provisioner.cpp:249] Using default backend 'copy'
I0629 05:34:49.189333  1291 sched.cpp:836] Sending SUBSCRIBE call to master@172.17.0.4:44620
I0629 05:34:49.189487  1291 sched.cpp:869] Will retry registration in 240.598779ms if necessary
I0629 05:34:49.189680  1298 master.cpp:2813] Received SUBSCRIBE call for framework 'default' at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620
I0629 05:34:49.189820  1298 master.cpp:2197] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
I0629 05:34:49.190564  1285 master.cpp:2890] Subscribing framework default with checkpointing enabled and capabilities [  ]
I0629 05:34:49.191561  1288 sched.cpp:759] Framework registered with 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.191642  1288 sched.cpp:773] Scheduler::registered took 28786ns
I0629 05:34:49.192240  1290 hierarchical.cpp:273] Added framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.192389  1290 hierarchical.cpp:1850] No allocations performed
I0629 05:34:49.192425  1290 hierarchical.cpp:1940] No inverse offers to send out!
I0629 05:34:49.192466  1290 hierarchical.cpp:1434] Performed allocation for 0 agents in 124015ns
I0629 05:34:49.194095  1262 cluster.cpp:448] Creating default 'local' authorizer
I0629 05:34:49.195989  1287 slave.cpp:231] Mesos agent started on (477)@172.17.0.4:44620
I0629 05:34:49.196306  1287 slave.cpp:232] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/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_MultipleSlaves_vp4q1X/credential" --default_role="*" --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/mesos/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_MultipleSlaves_vp4q1X/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_MultipleSlaves_vp4q1X/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_MultipleSlaves_vp4q1X/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/mem,posix/cpu" --launcher="posix" --launcher_dir="/mesos/mesos-1.3.1/_build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_exe:
cutors_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_MultipleSlaves_vp4q1X" --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_MultipleSlaves_rg4Xxg"
I0629 05:34:49.197198  1287 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_vp4q1X/credential'
I0629 05:34:49.197576  1287 slave.cpp:264] Agent using credential for: test-principal
I0629 05:34:49.197825  1287 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_vp4q1X/http_credentials'
I0629 05:34:49.198388  1287 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.198742  1287 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.199288  1287 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.199615  1287 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.200131  1287 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.200500  1287 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.202576  1287 slave.cpp:531] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:34:49.202916  1287 slave.cpp:539] Agent attributes: [  ]
I0629 05:34:49.203155  1287 slave.cpp:544] Agent hostname: f194a3049b2b
I0629 05:34:49.203505  1283 status_update_manager.cpp:177] Pausing sending status updates
I0629 05:34:49.205207  1287 state.cpp:62] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta'
I0629 05:34:49.205705  1290 status_update_manager.cpp:203] Recovering status update manager
I0629 05:34:49.205878  1292 containerizer.cpp:608] Recovering containerizer
I0629 05:34:49.208024  1292 provisioner.cpp:410] Provisioner recovery complete
I0629 05:34:49.208405  1296 slave.cpp:6075] Finished recovery
I0629 05:34:49.208894  1296 slave.cpp:6257] Querying resource estimator for oversubscribable resources
I0629 05:34:49.209347  1296 slave.cpp:924] New master detected at master@172.17.0.4:44620
I0629 05:34:49.209444  1296 slave.cpp:959] Detecting new master
I0629 05:34:49.209352  1285 status_update_manager.cpp:177] Pausing sending status updates
I0629 05:34:49.209681  1296 slave.cpp:6271] Received oversubscribable resources {} from the resource estimator
I0629 05:34:49.212635  1302 slave.cpp:986] Authenticating with master master@172.17.0.4:44620
I0629 05:34:49.212707  1302 slave.cpp:997] Using default CRAM-MD5 authenticatee
I0629 05:34:49.212905  1295 authenticatee.cpp:121] Creating new client SASL connection
I0629 05:34:49.213138  1281 master.cpp:7475] Authenticating slave(477)@172.17.0.4:44620
I0629 05:34:49.213235  1295 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(987)@172.17.0.4:44620
I0629 05:34:49.213745  1304 authenticator.cpp:98] Creating new server SASL connection
I0629 05:34:49.213994  1284 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0629 05:34:49.214021  1284 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0629 05:34:49.214237  1291 authenticator.cpp:204] Received SASL authentication start
I0629 05:34:49.214318  1291 authenticator.cpp:326] Authentication requires more steps
I0629 05:34:49.214432  1281 authenticatee.cpp:259] Received SASL authentication step
I0629 05:34:49.214556  1281 authenticator.cpp:232] Received SASL authentication step
I0629 05:34:49.214592  1281 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f194a3049b2b' server FQDN: 'f194a3049b2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0629 05:34:49.214692  1281 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0629 05:34:49.214745  1281 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0629 05:34:49.214831  1281 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f194a3049b2b' server FQDN: 'f194a3049b2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0629 05:34:49.214907  1281 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 05:34:49.214939  1281 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 05:34:49.214977  1281 authenticator.cpp:318] Authentication success
I0629 05:34:49.215189  1281 authenticatee.cpp:299] Authentication success
I0629 05:34:49.215294  1281 master.cpp:7505] Successfully authenticated principal 'test-principal' at slave(477)@172.17.0.4:44620
I0629 05:34:49.215394  1281 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(987)@172.17.0.4:44620
I0629 05:34:49.215713  1281 slave.cpp:1081] Successfully authenticated with master master@172.17.0.4:44620
I0629 05:34:49.215906  1281 slave.cpp:1509] Will retry registration in 8.252527ms if necessary
I0629 05:34:49.216203  1281 master.cpp:5429] Received register agent message from slave(477)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.216362  1281 master.cpp:3659] Authorizing agent with principal 'test-principal'
I0629 05:34:49.216933  1281 master.cpp:5564] Registering agent at slave(477)@172.17.0.4:44620 (f194a3049b2b) with id 00585c7a-2135-427f-8997-07274f586d94-S0
I0629 05:34:49.217460  1281 registrar.cpp:493] Applied 1 operations in 55942ns; attempting to update the registry
I0629 05:34:49.218307  1281 registrar.cpp:550] Successfully updated the registry in 748800ns
I0629 05:34:49.219125  1281 slave.cpp:4794] Received ping from slave-observer(464)@172.17.0.4:44620
I0629 05:34:49.219244  1285 master.cpp:5639] Registered agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:34:49.219667  1302 hierarchical.cpp:525] Added agent 00585c7a-2135-427f-8997-07274f586d94-S0 (f194a3049b2b) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0629 05:34:49.221338  1281 slave.cpp:1127] Registered with master master@172.17.0.4:44620; given agent ID 00585c7a-2135-427f-8997-07274f586d94-S0
I0629 05:34:49.221366  1281 fetcher.cpp:94] Clearing fetcher cache
I0629 05:34:49.221509  1289 status_update_manager.cpp:184] Resuming sending status updates
I0629 05:34:49.221676  1302 hierarchical.cpp:1940] No inverse offers to send out!
I0629 05:34:49.221735  1281 slave.cpp:1155] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/slave.info'
I0629 05:34:49.222362  1281 slave.cpp:1193] Forwarding total oversubscribed resources {}
I0629 05:34:49.222537  1282 master.cpp:7305] Sending 1 offers to framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620
I0629 05:34:49.221873  1302 hierarchical.cpp:1434] Performed allocation for 1 agents in 1.962052ms
I0629 05:34:49.222882  1282 master.cpp:6324] Received update of agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b) with total oversubscribed resources {}
I0629 05:34:49.223120  1289 sched.cpp:933] Scheduler::resourceOffers took 128533ns
I0629 05:34:49.225220  1283 master.cpp:3875] Processing ACCEPT call for offers: [ 00585c7a-2135-427f-8997-07274f586d94-O0 ] on agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b) for framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620
I0629 05:34:49.225334  1283 master.cpp:3426] Authorizing framework principal 'test-principal' to launch task 8508aa66-c6ec-4e93-b382-2090185e5ff8
I0629 05:34:49.228199  1283 master.cpp:9320] Adding task 8508aa66-c6ec-4e93-b382-2090185e5ff8 with resources cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] on agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.228688  1283 master.cpp:4531] Launching task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620 with resources cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] on agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.229477  1281 slave.cpp:1619] Got assigned task '8508aa66-c6ec-4e93-b382-2090185e5ff8' for framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.229653  1281 slave.cpp:6948] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/framework.info'
I0629 05:34:49.230069  1281 slave.cpp:6959] Checkpointing framework pid 'scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/framework.pid'
I0629 05:34:49.231281  1281 slave.cpp:1900] Authorizing task '8508aa66-c6ec-4e93-b382-2090185e5ff8' for framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.231344  1281 slave.cpp:6694] Authorizing framework principal 'test-principal' to launch task 8508aa66-c6ec-4e93-b382-2090185e5ff8
I0629 05:34:49.232254  1283 hierarchical.cpp:850] Updated allocation of framework 00585c7a-2135-427f-8997-07274f586d94-0000 on agent 00585c7a-2135-427f-8997-07274f586d94-S0 from cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] to cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000]
I0629 05:34:49.232334  1302 slave.cpp:2087] Launching task '8508aa66-c6ec-4e93-b382-2090185e5ff8' for framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.233369  1302 paths.cpp:573] Trying to chown '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/runs/7a2c0abf-1590-4806-af4d-c7aac1ca2dca' to user 'mesos'
I0629 05:34:49.233852  1302 slave.cpp:7401] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/executor.info'
I0629 05:34:49.234840  1302 slave.cpp:7038] Launching executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000 with resources cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32 in work directory '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/runs/7a2c0abf-1590-4806-af4d-c7aac1ca2dca'
I0629 05:34:49.235956  1302 slave.cpp:7429] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/runs/7a2c0abf-1590-4806-af4d-c7aac1ca2dca/tasks/8508aa66-c6ec-4e93-b382-2090185e5ff8/task.info'
I0629 05:34:49.236708  1302 slave.cpp:2316] Queued task '8508aa66-c6ec-4e93-b382-2090185e5ff8' for executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.236963  1302 slave.cpp:877] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/runs/7a2c0abf-1590-4806-af4d-c7aac1ca2dca'
I0629 05:34:49.237828  1299 containerizer.cpp:1001] Starting container 7a2c0abf-1590-4806-af4d-c7aac1ca2dca for executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.244124  1299 containerizer.cpp:1531] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.3.1\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.3.1\/_build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.4:44620"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg\/slaves\/00585c7a-2135-427f-8997-07274f586d94-S0\/frameworks\/00585c7a-2135-427f-8997-07274f586d94-0000\/executors\/8508aa66-c6ec-4e93-b382-2090185e5ff8\/runs\/7a2c0abf-1590-4806-af4d-c7aac1ca2dca"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiI3YTJjMGFiZi0xNTkwLTQ4MDYtYWY0ZC1jN2FhYzFjYTJkY2EiLCJlaWQiOiI4NTA4YWE2Ni1jNmVjLTRlOTMtYjM4Mi0yMDkwMTg1ZTVmZjgiLCJmaWQiOiIwMDU4NWM3YS0yMTM1LTQyN2YtODk5Ny0wNzI3NGY1ODZkOTQtMDAwMCJ9.kll0ZDe2YZUG_MW0sHTw0bB8i-_u4VARjkSixKYmIcM"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"8508aa66-c6ec-4e93-b382-2090185e5ff8"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"00585c7a-2135-427f-8997-07274f586d94-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":"00585c7a-2135-427f-8997-07274f586d94-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(477)@172.17.0.4:44620"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg\/slaves\/00585c7a-2135-427f-8997-07274f586d94-S0\/frameworks\/00585c7a-2135-427f-8997-07274f586d94-0000\/executors\/8508aa66-c6ec-4e93-b382-2090185e5ff8\/runs\/7a2c0abf-1590-4806-af4d-c7aac1ca2dca"}]},"user":"mesos","working_directory":"\/tmp\/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg\/slaves\/00585c7a-2135-427f-8997-07274f586d94-S0\/frameworks\/00585c7a-2135-427f-8997-07274f586d94-0000\/executors\/8508aa66-c6ec-4e93-b382-2090185e5ff8\/runs\/7a2c0abf-1590-4806-af4d-c7aac1ca2dca"}" --pipe_read="21" --pipe_write="22" --runtime_directory="/tmp/SlaveRecoveryTest_0_MultipleSlaves_vp4q1X/containers/7a2c0abf-1590-4806-af4d-c7aac1ca2dca" --unshare_namespace_mnt="false"'
I0629 05:34:49.248997  1299 launcher.cpp:140] Forked child with pid '15169' for container '7a2c0abf-1590-4806-af4d-c7aac1ca2dca'
I0629 05:34:49.249199  1299 containerizer.cpp:1630] Checkpointing container's forked pid 15169 to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/runs/7a2c0abf-1590-4806-af4d-c7aac1ca2dca/pids/forked.pid'
I0629 05:34:49.253118  1295 fetcher.cpp:353] Starting to fetch URIs for container: 7a2c0abf-1590-4806-af4d-c7aac1ca2dca, directory: /tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/runs/7a2c0abf-1590-4806-af4d-c7aac1ca2dca
I0629 05:34:49.458115 15220 exec.cpp:162] Version: 1.3.1
I0629 05:34:49.476415  1303 slave.cpp:3790] Got registration for executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000 from executor(1)@172.17.0.4:41916
I0629 05:34:49.477214  1303 slave.cpp:3876] Checkpointing executor pid 'executor(1)@172.17.0.4:41916' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S0/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/8508aa66-c6ec-4e93-b382-2090185e5ff8/runs/7a2c0abf-1590-4806-af4d-c7aac1ca2dca/pids/libprocess.pid'
I0629 05:34:49.480761  1303 slave.cpp:2529] Sending queued task '8508aa66-c6ec-4e93-b382-2090185e5ff8' to executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000 at executor(1)@172.17.0.4:41916
I0629 05:34:49.481364 15217 exec.cpp:237] Executor registered on agent 00585c7a-2135-427f-8997-07274f586d94-S0
Received SUBSCRIBED event
Subscribed executor on f194a3049b2b
Received LAUNCH event
Starting task 8508aa66-c6ec-4e93-b382-2090185e5ff8
Running '/mesos/mesos-1.3.1/_build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
Forked command at 15222
I0629 05:34:49.499444  1283 slave.cpp:4264] Handling status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 from executor(1)@172.17.0.4:41916
I0629 05:34:49.501641  1283 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.501798  1283 status_update_manager.cpp:500] Creating StatusUpdate stream for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.502578  1283 status_update_manager.cpp:832] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.502949  1283 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 to the agent
I0629 05:34:49.503326  1293 slave.cpp:4704] Forwarding the update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 to master@172.17.0.4:44620
I0629 05:34:49.503659  1293 slave.cpp:4598] Status update manager successfully handled status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.503712  1293 slave.cpp:4614] Sending acknowledgement for status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 to executor(1)@172.17.0.4:41916
I0629 05:34:49.503718  1283 master.cpp:6469] Status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 from agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.503780  1283 master.cpp:6537] Forwarding status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.504158  1295 sched.cpp:1041] Scheduler::statusUpdate took 29960ns
I0629 05:34:49.504429  1283 master.cpp:8568] Updating the state of task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0629 05:34:49.504643  1283 master.cpp:5194] Processing ACKNOWLEDGE call 5f45b8cb-987a-49e6-a988-14d6cffceb0e for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620 on agent 00585c7a-2135-427f-8997-07274f586d94-S0
I0629 05:34:49.505206  1299 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.505348  1299 status_update_manager.cpp:832] Checkpointing ACK for status update TASK_RUNNING (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.505607  1295 slave.cpp:3510] Status update manager successfully handled status update acknowledgement (UUID: 5f45b8cb-987a-49e6-a988-14d6cffceb0e) for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.508642  1262 containerizer.cpp:221] Using isolation: filesystem/posix,posix/mem,posix/cpu,network/cni
W0629 05:34:49.509165  1262 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0629 05:34:49.509418  1262 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0629 05:34:49.509459  1262 provisioner.cpp:249] Using default backend 'copy'
I0629 05:34:49.512902  1262 cluster.cpp:448] Creating default 'local' authorizer
I0629 05:34:49.514550  1304 slave.cpp:231] Mesos agent started on (478)@172.17.0.4:44620
I0629 05:34:49.514571  1304 slave.cpp:232] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/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_MultipleSlaves_RRhxmJ/credential" --default_role="*" --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/mesos/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_MultipleSlaves_RRhxmJ/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_MultipleSlaves_RRhxmJ/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_MultipleSlaves_RRhxmJ/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/mem,posix/cpu" --launcher="posix" --launcher_dir="/mesos/mesos-1.3.1/_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_MultipleSlaves_RRhxmJ" --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_MultipleSlaves_NhLh70"
I0629 05:34:49.514976  1304 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_RRhxmJ/credential'
I0629 05:34:49.515110  1304 slave.cpp:264] Agent using credential for: test-principal
I0629 05:34:49.515130  1304 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_RRhxmJ/http_credentials'
I0629 05:34:49.515373  1304 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.515499  1304 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.515764  1304 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.515861  1304 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.516013  1304 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.516105  1304 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.517519  1304 slave.cpp:531] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:34:49.517596  1304 slave.cpp:539] Agent attributes: [  ]
I0629 05:34:49.517607  1304 slave.cpp:544] Agent hostname: f194a3049b2b
I0629 05:34:49.517782  1298 status_update_manager.cpp:177] Pausing sending status updates
I0629 05:34:49.519106  1288 state.cpp:62] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta'
I0629 05:34:49.519532  1303 status_update_manager.cpp:203] Recovering status update manager
I0629 05:34:49.519798  1302 containerizer.cpp:608] Recovering containerizer
I0629 05:34:49.521394  1290 provisioner.cpp:410] Provisioner recovery complete
I0629 05:34:49.521749  1302 slave.cpp:6075] Finished recovery
I0629 05:34:49.522305  1302 slave.cpp:6257] Querying resource estimator for oversubscribable resources
I0629 05:34:49.522594  1293 status_update_manager.cpp:177] Pausing sending status updates
I0629 05:34:49.522620  1284 slave.cpp:924] New master detected at master@172.17.0.4:44620
I0629 05:34:49.522752  1284 slave.cpp:959] Detecting new master
I0629 05:34:49.522882  1284 slave.cpp:6271] Received oversubscribable resources {} from the resource estimator
I0629 05:34:49.531033  1286 slave.cpp:986] Authenticating with master master@172.17.0.4:44620
I0629 05:34:49.531219  1286 slave.cpp:997] Using default CRAM-MD5 authenticatee
I0629 05:34:49.531548  1304 authenticatee.cpp:121] Creating new client SASL connection
I0629 05:34:49.531965  1285 master.cpp:7475] Authenticating slave(478)@172.17.0.4:44620
I0629 05:34:49.532126  1300 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(988)@172.17.0.4:44620
I0629 05:34:49.532452  1299 authenticator.cpp:98] Creating new server SASL connection
I0629 05:34:49.532738  1281 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0629 05:34:49.532770  1281 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0629 05:34:49.532867  1281 authenticator.cpp:204] Received SASL authentication start
I0629 05:34:49.532937  1281 authenticator.cpp:326] Authentication requires more steps
I0629 05:34:49.533179  1283 authenticatee.cpp:259] Received SASL authentication step
I0629 05:34:49.533318  1287 authenticator.cpp:232] Received SASL authentication step
I0629 05:34:49.533350  1287 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f194a3049b2b' server FQDN: 'f194a3049b2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0629 05:34:49.533365  1287 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0629 05:34:49.533408  1287 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0629 05:34:49.533439  1287 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f194a3049b2b' server FQDN: 'f194a3049b2b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0629 05:34:49.533452  1287 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0629 05:34:49.533462  1287 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0629 05:34:49.533479  1287 authenticator.cpp:318] Authentication success
I0629 05:34:49.533558  1283 authenticatee.cpp:299] Authentication success
I0629 05:34:49.533628  1289 master.cpp:7505] Successfully authenticated principal 'test-principal' at slave(478)@172.17.0.4:44620
I0629 05:34:49.533654  1288 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(988)@172.17.0.4:44620
I0629 05:34:49.534018  1296 slave.cpp:1081] Successfully authenticated with master master@172.17.0.4:44620
I0629 05:34:49.534204  1296 slave.cpp:1509] Will retry registration in 15.093465ms if necessary
I0629 05:34:49.534384  1282 master.cpp:5429] Received register agent message from slave(478)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.534497  1282 master.cpp:3659] Authorizing agent with principal 'test-principal'
I0629 05:34:49.534981  1302 master.cpp:5564] Registering agent at slave(478)@172.17.0.4:44620 (f194a3049b2b) with id 00585c7a-2135-427f-8997-07274f586d94-S1
I0629 05:34:49.535529  1293 registrar.cpp:493] Applied 1 operations in 87532ns; attempting to update the registry
I0629 05:34:49.536274  1293 registrar.cpp:550] Successfully updated the registry in 677888ns
I0629 05:34:49.536873  1295 slave.cpp:4794] Received ping from slave-observer(465)@172.17.0.4:44620
I0629 05:34:49.537142  1287 master.cpp:5639] Registered agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:34:49.537199  1281 slave.cpp:1127] Registered with master master@172.17.0.4:44620; given agent ID 00585c7a-2135-427f-8997-07274f586d94-S1
I0629 05:34:49.537235  1281 fetcher.cpp:94] Clearing fetcher cache
I0629 05:34:49.537374  1288 status_update_manager.cpp:184] Resuming sending status updates
I0629 05:34:49.537490  1291 hierarchical.cpp:525] Added agent 00585c7a-2135-427f-8997-07274f586d94-S1 (f194a3049b2b) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0629 05:34:49.537608  1281 slave.cpp:1155] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/slave.info'
I0629 05:34:49.537941  1281 slave.cpp:1193] Forwarding total oversubscribed resources {}
I0629 05:34:49.538117  1301 master.cpp:6324] Received update of agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b) with total oversubscribed resources {}
I0629 05:34:49.538739  1291 hierarchical.cpp:1940] No inverse offers to send out!
I0629 05:34:49.538815  1291 hierarchical.cpp:1434] Performed allocation for 1 agents in 1.172173ms
I0629 05:34:49.539160  1297 master.cpp:7305] Sending 1 offers to framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620
I0629 05:34:49.539610  1281 sched.cpp:933] Scheduler::resourceOffers took 106881ns
I0629 05:34:49.541399  1300 master.cpp:3875] Processing ACCEPT call for offers: [ 00585c7a-2135-427f-8997-07274f586d94-O1 ] on agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b) for framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620
I0629 05:34:49.541489  1300 master.cpp:3426] Authorizing framework principal 'test-principal' to launch task 75ccacb0-ce25-45e5-accd-8e3719692285
I0629 05:34:49.543797  1288 master.cpp:9320] Adding task 75ccacb0-ce25-45e5-accd-8e3719692285 with resources cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] on agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.544189  1288 master.cpp:4531] Launching task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620 with resources cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] on agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.544966  1283 slave.cpp:1619] Got assigned task '75ccacb0-ce25-45e5-accd-8e3719692285' for framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.545166  1283 slave.cpp:6948] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/framework.info'
I0629 05:34:49.545606  1283 slave.cpp:6959] Checkpointing framework pid 'scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/framework.pid'
I0629 05:34:49.546424  1283 slave.cpp:1900] Authorizing task '75ccacb0-ce25-45e5-accd-8e3719692285' for framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.546491  1283 slave.cpp:6694] Authorizing framework principal 'test-principal' to launch task 75ccacb0-ce25-45e5-accd-8e3719692285
I0629 05:34:49.546663  1303 hierarchical.cpp:850] Updated allocation of framework 00585c7a-2135-427f-8997-07274f586d94-0000 on agent 00585c7a-2135-427f-8997-07274f586d94-S1 from cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] to cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000]
I0629 05:34:49.547534  1295 slave.cpp:2087] Launching task '75ccacb0-ce25-45e5-accd-8e3719692285' for framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.548120  1295 paths.cpp:573] Trying to chown '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/runs/35b78f55-e705-4e85-9231-c85ddd5c31bb' to user 'mesos'
I0629 05:34:49.548421  1295 slave.cpp:7401] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/executor.info'
I0629 05:34:49.548984  1295 slave.cpp:7038] Launching executor '75ccacb0-ce25-45e5-accd-8e3719692285' of framework 00585c7a-2135-427f-8997-07274f586d94-0000 with resourc:
es cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32 in work directory '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/runs/35b78f55-e705-4e85-9231-c85ddd5c31bb'
I0629 05:34:49.549841  1295 slave.cpp:7429] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/runs/35b78f55-e705-4e85-9231-c85ddd5c31bb/tasks/75ccacb0-ce25-45e5-accd-8e3719692285/task.info'
I0629 05:34:49.550302  1295 slave.cpp:2316] Queued task '75ccacb0-ce25-45e5-accd-8e3719692285' for executor '75ccacb0-ce25-45e5-accd-8e3719692285' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.550391  1295 slave.cpp:877] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/runs/35b78f55-e705-4e85-9231-c85ddd5c31bb'
I0629 05:34:49.550964  1297 containerizer.cpp:1001] Starting container 35b78f55-e705-4e85-9231-c85ddd5c31bb for executor '75ccacb0-ce25-45e5-accd-8e3719692285' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.555903  1303 containerizer.cpp:1531] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.3.1\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.3.1\/_build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.4:44620"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/SlaveRecoveryTest_0_MultipleSlaves_NhLh70\/slaves\/00585c7a-2135-427f-8997-07274f586d94-S1\/frameworks\/00585c7a-2135-427f-8997-07274f586d94-0000\/executors\/75ccacb0-ce25-45e5-accd-8e3719692285\/runs\/35b78f55-e705-4e85-9231-c85ddd5c31bb"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIzNWI3OGY1NS1lNzA1LTRlODUtOTIzMS1jODVkZGQ1YzMxYmIiLCJlaWQiOiI3NWNjYWNiMC1jZTI1LTQ1ZTUtYWNjZC04ZTM3MTk2OTIyODUiLCJmaWQiOiIwMDU4NWM3YS0yMTM1LTQyN2YtODk5Ny0wNzI3NGY1ODZkOTQtMDAwMCJ9.56LqKdl0n8pxy8i028nEdby_7fP2gpwkVDUYJXQ08IA"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"75ccacb0-ce25-45e5-accd-8e3719692285"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"00585c7a-2135-427f-8997-07274f586d94-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":"00585c7a-2135-427f-8997-07274f586d94-S1"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(478)@172.17.0.4:44620"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/SlaveRecoveryTest_0_MultipleSlaves_NhLh70\/slaves\/00585c7a-2135-427f-8997-07274f586d94-S1\/frameworks\/00585c7a-2135-427f-8997-07274f586d94-0000\/executors\/75ccacb0-ce25-45e5-accd-8e3719692285\/runs\/35b78f55-e705-4e85-9231-c85ddd5c31bb"}]},"user":"mesos","working_directory":"\/tmp\/SlaveRecoveryTest_0_MultipleSlaves_NhLh70\/slaves\/00585c7a-2135-427f-8997-07274f586d94-S1\/frameworks\/00585c7a-2135-427f-8997-07274f586d94-0000\/executors\/75ccacb0-ce25-45e5-accd-8e3719692285\/runs\/35b78f55-e705-4e85-9231-c85ddd5c31bb"}" --pipe_read="25" --pipe_write="27" --runtime_directory="/tmp/SlaveRecoveryTest_0_MultipleSlaves_RRhxmJ/containers/35b78f55-e705-4e85-9231-c85ddd5c31bb" --unshare_namespace_mnt="false"'
I0629 05:34:49.559849  1303 launcher.cpp:140] Forked child with pid '15236' for container '35b78f55-e705-4e85-9231-c85ddd5c31bb'
I0629 05:34:49.560117  1303 containerizer.cpp:1630] Checkpointing container's forked pid 15236 to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/runs/35b78f55-e705-4e85-9231-c85ddd5c31bb/pids/forked.pid'
I0629 05:34:49.563535  1293 fetcher.cpp:353] Starting to fetch URIs for container: 35b78f55-e705-4e85-9231-c85ddd5c31bb, directory: /tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/runs/35b78f55-e705-4e85-9231-c85ddd5c31bb
I0629 05:34:49.779817 15268 exec.cpp:162] Version: 1.3.1
I0629 05:34:49.794827  1287 slave.cpp:3790] Got registration for executor '75ccacb0-ce25-45e5-accd-8e3719692285' of framework 00585c7a-2135-427f-8997-07274f586d94-0000 from executor(1)@172.17.0.4:35844
I0629 05:34:49.795470  1287 slave.cpp:3876] Checkpointing executor pid 'executor(1)@172.17.0.4:35844' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_NhLh70/meta/slaves/00585c7a-2135-427f-8997-07274f586d94-S1/frameworks/00585c7a-2135-427f-8997-07274f586d94-0000/executors/75ccacb0-ce25-45e5-accd-8e3719692285/runs/35b78f55-e705-4e85-9231-c85ddd5c31bb/pids/libprocess.pid'
I0629 05:34:49.798254  1293 slave.cpp:2529] Sending queued task '75ccacb0-ce25-45e5-accd-8e3719692285' to executor '75ccacb0-ce25-45e5-accd-8e3719692285' of framework 00585c7a-2135-427f-8997-07274f586d94-0000 at executor(1)@172.17.0.4:35844
I0629 05:34:49.798952 15286 exec.cpp:237] Executor registered on agent 00585c7a-2135-427f-8997-07274f586d94-S1
Received SUBSCRIBED event
Subscribed executor on f194a3049b2b
Received LAUNCH event
Starting task 75ccacb0-ce25-45e5-accd-8e3719692285
Running '/mesos/mesos-1.3.1/_build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
Forked command at 15290
I0629 05:34:49.811517  1286 slave.cpp:4264] Handling status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 from executor(1)@172.17.0.4:35844
I0629 05:34:49.813228  1291 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.813277  1291 status_update_manager.cpp:500] Creating StatusUpdate stream for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.813843  1291 status_update_manager.cpp:832] Checkpointing UPDATE for status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.814107  1291 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 to the agent
I0629 05:34:49.814404  1294 slave.cpp:4704] Forwarding the update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 to master@172.17.0.4:44620
I0629 05:34:49.814625  1294 slave.cpp:4598] Status update manager successfully handled status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.814676  1294 slave.cpp:4614] Sending acknowledgement for status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 to executor(1)@172.17.0.4:35844
I0629 05:34:49.814777  1290 master.cpp:6469] Status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 from agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.814841  1290 master.cpp:6537] Forwarding status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.815068  1290 master.cpp:8568] Updating the state of task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I0629 05:34:49.815171  1294 sched.cpp:1041] Scheduler::statusUpdate took 22538ns
I0629 05:34:49.815394  1286 master.cpp:5194] Processing ACKNOWLEDGE call fb988238-9549-42c6-8c2d-ec1477fd2dcc for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000 (default) at scheduler-356010b1-a9ea-41bb-b9b3-2ce391f6c82d@172.17.0.4:44620 on agent 00585c7a-2135-427f-8997-07274f586d94-S1
I0629 05:34:49.815752  1303 status_update_manager.cpp:395] Received status update acknowledgement (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.815883  1303 status_update_manager.cpp:832] Checkpointing ACK for status update TASK_RUNNING (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.816107  1304 slave.cpp:3510] Status update manager successfully handled status update acknowledgement (UUID: fb988238-9549-42c6-8c2d-ec1477fd2dcc) for task 75ccacb0-ce25-45e5-accd-8e3719692285 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.816460  1295 slave.cpp:796] Agent terminating
I0629 05:34:49.816740  1296 master.cpp:1313] Agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b) disconnected
I0629 05:34:49.816761  1283 slave.cpp:796] Agent terminating
I0629 05:34:49.816768  1296 master.cpp:3197] Disconnecting agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.816869  1296 master.cpp:3216] Deactivating agent 00585c7a-2135-427f-8997-07274f586d94-S0 at slave(477)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.817502  1262 containerizer.cpp:221] Using isolation: filesystem/posix,posix/mem,posix/cpu,network/cni
W0629 05:34:49.817950  1262 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0629 05:34:49.818045  1262 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0629 05:34:49.818083  1262 provisioner.cpp:249] Using default backend 'copy'
I0629 05:34:49.818359  1299 hierarchical.cpp:653] Agent 00585c7a-2135-427f-8997-07274f586d94-S0 deactivated
I0629 05:34:49.818377  1296 master.cpp:1313] Agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b) disconnected
I0629 05:34:49.818404  1296 master.cpp:3197] Disconnecting agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.818467  1296 master.cpp:3216] Deactivating agent 00585c7a-2135-427f-8997-07274f586d94-S1 at slave(478)@172.17.0.4:44620 (f194a3049b2b)
I0629 05:34:49.818665  1290 hierarchical.cpp:653] Agent 00585c7a-2135-427f-8997-07274f586d94-S1 deactivated
I0629 05:34:49.823856  1262 cluster.cpp:448] Creating default 'local' authorizer
I0629 05:34:49.827705  1262 containerizer.cpp:221] Using isolation: filesystem/posix,posix/mem,posix/cpu,network/cni
W0629 05:34:49.828301  1262 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0629 05:34:49.828450  1262 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0629 05:34:49.828493  1262 provisioner.cpp:249] Using default backend 'copy'
I0629 05:34:49.831936  1291 slave.cpp:231] Mesos agent started on (479)@172.17.0.4:44620
I0629 05:34:49.832227  1291 slave.cpp:232] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/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_MultipleSlaves_vp4q1X/credential" --default_role="*" --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/mesos/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_MultipleSlaves_vp4q1X/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_MultipleSlaves_vp4q1X/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_MultipleSlaves_vp4q1X/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/mem,posix/cpu" --launcher="posix" --launcher_dir="/mesos/mesos-1.3.1/_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_MultipleSlaves_vp4q1X" --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_MultipleSlaves_rg4Xxg"
I0629 05:34:49.833976  1291 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_vp4q1X/credential'
I0629 05:34:49.834383  1262 cluster.cpp:448] Creating default 'local' authorizer
I0629 05:34:49.834656  1291 slave.cpp:264] Agent using credential for: test-principal
I0629 05:34:49.835134  1291 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_vp4q1X/http_credentials'
I0629 05:34:49.836670  1298 slave.cpp:231] Mesos agent started on (480)@172.17.0.4:44620
I0629 05:34:49.838234  1298 slave.cpp:232] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/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_MultipleSlaves_RRhxmJ/credential" --default_role="*" --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/mesos/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_MultipleSlaves_RRhxmJ/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_MultipleSlaves_RRhxmJ/fetch" --fetc:
her_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_MultipleSlaves_RRhxmJ/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="filesystem/posix,posix/mem,posix/cpu" --launcher="posix" --launcher_dir="/mesos/mesos-1.3.1/_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_MultipleSlaves_RRhxmJ" --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_MultipleSlaves_NhLh70"
I0629 05:34:49.838778  1298 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_RRhxmJ/credential'
I0629 05:34:49.838932  1298 slave.cpp:264] Agent using credential for: test-principal
I0629 05:34:49.838944  1291 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.838954  1298 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_RRhxmJ/http_credentials'
I0629 05:34:49.839102  1291 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.839241  1298 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.839361  1298 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
I0629 05:34:49.839606  1298 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.839721  1298 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.839815  1291 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.840064  1291 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
I0629 05:34:49.840298  1291 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.840409  1291 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.840684  1298 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.840802  1298 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
I0629 05:34:49.842509  1291 slave.cpp:531] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:34:49.842666  1298 slave.cpp:531] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0629 05:34:49.842864  1298 slave.cpp:539] Agent attributes: [  ]
I0629 05:34:49.843027  1298 slave.cpp:544] Agent hostname: f194a3049b2b
I0629 05:34:49.842757  1291 slave.cpp:539] Agent attributes: [  ]
I0629 05:34:49.843235  1291 slave.cpp:544] Agent hostname: f194a3049b2b
I0629 05:34:49.843406  1285 status_update_manager.cpp:177] Pausing sending status updates
I0629 05:34:49.843595  1282 status_update_manager.cpp:177] Pausing sending status updates
*** Error in `/mesos/mesos-1.3.1/_build/src/.libs/lt-mesos-tests': double free or corruption (fasttop): 0x00002acb7c00e340 ***
*** Aborted at 1498714489 (unix time) try "date -d @1498714489" if you are using GNU date ***
I0629 05:34:49.845293  1304 state.cpp:62] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta'
I0629 05:34:49.845422  1304 state.cpp:710] No committed checkpointed resources found at '/tmp/SlaveRecoveryTest_0_MultipleSlaves_rg4Xxg/meta/resources/resources.info'
PC: @     0x2acb52e7cc37 (unknown)
*** SIGABRT (@0x3e8000004ee) received by PID 1262 (TID 0x2acb5ddc3700) from PID 1262; stack trace: ***
I0629 05:34:49.851711  1287 fetcher.cpp:94] Clearing fetcher cache
I0629 05:34:49.851817  1287 slave.cpp:6166] Recovering framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.851909  1287 slave.cpp:7146] Recovering executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
    @     0x2acb52c38330 (unknown)
    @     0x2acb52e7cc37 (unknown)
    @     0x2acb52e80028 (unknown)
    @     0x2acb52eb92a4 (unknown)
    @     0x2acb52ec582e (unknown)
I0629 05:34:49.853229  1299 status_update_manager.cpp:203] Recovering status update manager
I0629 05:34:49.853256  1299 status_update_manager.cpp:211] Recovering executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.853351  1299 status_update_manager.cpp:500] Creating StatusUpdate stream for task 8508aa66-c6ec-4e93-b382-2090185e5ff8 of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.854063  1299 status_update_manager.cpp:808] Replaying status update stream for task 8508aa66-c6ec-4e93-b382-2090185e5ff8
I0629 05:34:49.854976  1299 containerizer.cpp:608] Recovering containerizer
I0629 05:34:49.855249  1299 containerizer.cpp:664] Recovering container 7a2c0abf-1590-4806-af4d-c7aac1ca2dca for executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.859482  1288 provisioner.cpp:410] Provisioner recovery complete
I0629 05:34:49.861148  1289 slave.cpp:5959] Sending reconnect request to executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000 at executor(1)@172.17.0.4:41916
I0629 05:34:49.862918 15213 exec.cpp:283] Received reconnect request from agent 00585c7a-2135-427f-8997-07274f586d94-S0
I0629 05:34:49.865195  1289 slave.cpp:3972] Received re-registration message from executor '8508aa66-c6ec-4e93-b382-2090185e5ff8' of framework 00585c7a-2135-427f-8997-07274f586d94-0000
I0629 05:34:49.866827 15205 exec.cpp:260] Executor re-registered on agent 00585c7a-2135-427f-8997-07274f586d94-S0
    @     0x2acb4f72d1ec _ZNSt14_Function_base13_Base_managerIZN7process5deferIN5mesos8internal5slave5SlaveEiiSt12_PlaceholderILi1EES7_ILi2EEEENS1_9_DeferredIDTcl4bindadsrSt8functionIFvT0_T1_EEclcvSF__Efp1_fp2_EEEERKNS1_3PIDIT_EEMSJ_FvSC_SD_ET2_T3_EUliiE_E10_M_destroyERSt9_Any_dataSt17integral_constantIbLb0EE
Received SUBSCRIBED event
Subscribed executor on f194a3049b2b
    @     0x2acb4f7177f5 _ZNSt14_Function_base13_Base_managerIZN7process5deferIN5mesos8internal5slave5SlaveEiiSt12_PlaceholderILi1EES7_ILi2EEEENS1_9_DeferredIDTcl4bindadsrSt8functionIFvT0_T1_EEclcvSF__Efp1_fp2_EEEERKNS1_3PIDIT_EEMSJ_FvSC_SD_ET2_T3_EUliiE_E10_M_managerERSt9_Any_dataRKST_St18_Manager_operation
    @     0x5611dd569303 std::_Function_base::~_Function_base()
    @     0x2acb4f6d124e std::function<>::~function()
    @     0x2acb4f6d2618 std::_Head_base<>::~_Head_base()
    @     0x2acb4f6d2632 std::_Tuple_impl<>::~_Tuple_impl()
    @     0x2acb4f6d264c _ZNSt5tupleIJSt8functionIFviiEESt12_PlaceholderILi1EES3_ILi2EEEED2Ev
    @     0x2acb4f6d266a std::_Bind<>::~_Bind()
    @     0x2acb4f72d3e1 std::_Function_base::_Base_manager<>::_M_destroy()
    @     0x2acb4f717ad1 std::_Function_base::_Base_manager<>::_M_manager()
    @     0x5611dd569303 std::_Function_base::~_Function_base()
    @     0x2acb4f6d124e std::function<>::~function()
    @     0x2acb4f68021c os::internal::configureSignal()
    @     0x2acb4f685c4d mesos::internal::slave::Slave::initialize()
    @     0x2acb50480193 process::ProcessManager::resume()
    @     0x2acb5047cc78 _ZZN7process14ProcessManager12init_threadsEvENKUt_clEv
    @     0x2acb5048e17e _ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUt_vEE9_M_invokeIIEEEvSt12_Index_tupleIIXspT_EEE
    @     0x2acb5048e0d5 _ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUt_vEEclEv
    @     0x2acb5048e06e _ZNSt6thread5_ImplISt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUt_vEEE6_M_runEv
    @     0x2acb524b9a60 (unknown)
    @     0x2acb52c30184 start_thread
    @     0x2acb52f43ffd (unknown)
I0629 05:34:50.253844 15197 exec.cpp:508] Agent exited, but framework has checkpointing enabled. Waiting 15mins to reconnect with agent 00585c7a-2135-427f-8997-07274f586d94-S0
I0629 05:34:50.254472 15200 exec.cpp:517] Agent exited ... shutting down
Received SHUTDOWN event
Shutting down
Sending SIGTERM to process tree at pid 15222
I0629 05:34:50.255748 15288 exec.cpp:508] Agent exited, but framework has checkpointing enabled. Waiting 15mins to reconnect with agent 00585c7a-2135-427f-8997-07274f586d94-S1
Sent SIGTERM to the following process trees:
[ 
-+- 15222 sh -c sleep 1000 
 \--- 15250 sleep 1000 
]
Scheduling escalation to SIGKILL in 3secs from now
Command terminated with signal Terminated (pid: 15222)
E0629 05:34:50.267503 15208 process.cpp:2450] Failed to shutdown socket with fd 7, address 172.17.0.4:38522: Transport endpoint is not connected
E0629 05:34:51.269366 15221 process.cpp:951] Failed to accept socket: future discarded
make[4]: *** [check-local] Aborted (core dumped)
make[4]: Leaving directory `/mesos/mesos-1.3.1/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-1.3.1/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-1.3.1/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-1.3.1/_build'
make: *** [distcheck] Error 1

Attachments

Issue Links

is blocked by

MESOS-8084 Double free corruption in tests due to parallel manipulation of signal and control handlers.

Resolved

Activity

People

Assignee:: Unassigned

Reporter:: Vinod Kone

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 29/Jun/17 17:41

Updated:: 21/Oct/17 00:04

Resolved:: 21/Oct/17 00:04