[
https://issues.apache.org/jira/browse/MESOS-4404?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15654101#comment-15654101
]
Alexander Rukletsov commented on MESOS-4404:
--------------------------------------------
Saw one more failure in Apache CI:
{noformat}
[ RUN ] SlaveTest.HTTPSchedulerSlaveRestart
I1110 01:47:03.995028 30949 cluster.cpp:158] Creating default 'local' authorizer
I1110 01:47:03.997442 30949 leveldb.cpp:174] Opened db in 2.129383ms
I1110 01:47:03.997962 30949 leveldb.cpp:181] Compacted db in 489488ns
I1110 01:47:03.998003 30949 leveldb.cpp:196] Created db iterator in 17567ns
I1110 01:47:03.998016 30949 leveldb.cpp:202] Seeked to beginning of db in 1688ns
I1110 01:47:03.998024 30949 leveldb.cpp:271] Iterated through 0 keys in the db
in 347ns
I1110 01:47:03.998062 30949 replica.cpp:776] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I1110 01:47:03.998610 30982 recover.cpp:451] Starting replica recovery
I1110 01:47:03.998934 30982 recover.cpp:477] Replica is in EMPTY status
I1110 01:47:04.000113 30980 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from __req_res__(6273)@172.17.0.2:55933
I1110 01:47:04.000543 30968 recover.cpp:197] Received a recover response from a
replica in EMPTY status
I1110 01:47:04.000973 30981 recover.cpp:568] Updating replica status to STARTING
I1110 01:47:04.001570 30968 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 385848ns
I1110 01:47:04.001596 30968 replica.cpp:320] Persisted replica status to
STARTING
I1110 01:47:04.001797 30972 recover.cpp:477] Replica is in STARTING status
I1110 01:47:04.002784 30983 master.cpp:380] Master
0c3821c4-3478-4e0b-8621-6ed22c08bdda (2aa403d92175) started on 172.17.0.2:55933
I1110 01:47:04.002820 30983 master.cpp:382] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/NkUSvj/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--http_authenticators="basic" --http_framework_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--quiet="false" --recovery_agent_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_gc_interval="15mins" --registry_max_agent_age="2weeks"
--registry_max_agent_count="102400" --registry_store_timeout="100secs"
--registry_strict="false" --root_submissions="true" --user_sorter="drf"
--version="false" --webui_dir="/mesos/mesos-1.2.0/_inst/share/mesos/webui"
--work_dir="/tmp/NkUSvj/master" --zk_session_timeout="10secs"
I1110 01:47:04.003515 30983 master.cpp:432] Master only allowing authenticated
frameworks to register
I1110 01:47:04.003500 30981 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from __req_res__(6274)@172.17.0.2:55933
I1110 01:47:04.003552 30983 master.cpp:446] Master only allowing authenticated
agents to register
I1110 01:47:04.003653 30983 master.cpp:459] Master only allowing authenticated
HTTP frameworks to register
I1110 01:47:04.003700 30983 credentials.hpp:37] Loading credentials for
authentication from '/tmp/NkUSvj/credentials'
I1110 01:47:04.003860 30981 recover.cpp:197] Received a recover response from a
replica in STARTING status
I1110 01:47:04.004154 30983 master.cpp:504] Using default 'crammd5'
authenticator
I1110 01:47:04.004365 30983 http.cpp:895] Using default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1110 01:47:04.004638 30983 http.cpp:895] Using default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1110 01:47:04.004794 30983 http.cpp:895] Using default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1110 01:47:04.004885 30975 recover.cpp:568] Updating replica status to VOTING
I1110 01:47:04.005070 30983 master.cpp:584] Authorization enabled
I1110 01:47:04.005408 30980 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 286810ns
I1110 01:47:04.005434 30980 replica.cpp:320] Persisted replica status to VOTING
I1110 01:47:04.005494 30970 whitelist_watcher.cpp:77] No whitelist given
I1110 01:47:04.005511 30969 hierarchical.cpp:149] Initialized hierarchical
allocator process
I1110 01:47:04.005564 30980 recover.cpp:582] Successfully joined the Paxos group
I1110 01:47:04.005795 30980 recover.cpp:466] Recover process terminated
I1110 01:47:04.008816 30978 master.cpp:2033] Elected as the leading master!
I1110 01:47:04.008860 30978 master.cpp:1560] Recovering from registrar
I1110 01:47:04.009059 30974 registrar.cpp:329] Recovering registrar
I1110 01:47:04.009763 30983 log.cpp:553] Attempting to start the writer
I1110 01:47:04.011137 30982 replica.cpp:493] Replica received implicit promise
request from __req_res__(6275)@172.17.0.2:55933 with proposal 1
I1110 01:47:04.011494 30982 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 323844ns
I1110 01:47:04.011518 30982 replica.cpp:342] Persisted promised to 1
I1110 01:47:04.012137 30977 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I1110 01:47:04.013375 30976 replica.cpp:388] Replica received explicit promise
request from __req_res__(6276)@172.17.0.2:55933 for position 0 with proposal 2
I1110 01:47:04.013548 30976 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 131140ns
I1110 01:47:04.013573 30976 replica.cpp:708] Persisted action NOP at position 0
I1110 01:47:04.014632 30973 replica.cpp:537] Replica received write request for
position 0 from __req_res__(6277)@172.17.0.2:55933
I1110 01:47:04.014699 30973 leveldb.cpp:436] Reading position from leveldb took
32867ns
I1110 01:47:04.014996 30973 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 253465ns
I1110 01:47:04.015018 30973 replica.cpp:708] Persisted action NOP at position 0
I1110 01:47:04.015641 30979 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I1110 01:47:04.015816 30979 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 126745ns
I1110 01:47:04.015841 30979 replica.cpp:708] Persisted action NOP at position 0
I1110 01:47:04.016517 30971 log.cpp:569] Writer started with ending position 0
I1110 01:47:04.017593 30978 leveldb.cpp:436] Reading position from leveldb took
43510ns
I1110 01:47:04.018528 30970 registrar.cpp:362] Successfully fetched the
registry (0B) in 9.412096ms
I1110 01:47:04.018641 30970 registrar.cpp:461] Applied 1 operations in 17550ns;
attempting to update the registry
I1110 01:47:04.019273 30968 log.cpp:577] Attempting to append 168 bytes to the
log
I1110 01:47:04.019390 30969 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I1110 01:47:04.020421 30981 replica.cpp:537] Replica received write request for
position 1 from __req_res__(6278)@172.17.0.2:55933
I1110 01:47:04.020797 30981 leveldb.cpp:341] Persisting action (187 bytes) to
leveldb took 336147ns
I1110 01:47:04.020822 30981 replica.cpp:708] Persisted action APPEND at
position 1
I1110 01:47:04.021445 30970 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I1110 01:47:04.021608 30970 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 131377ns
I1110 01:47:04.021641 30970 replica.cpp:708] Persisted action APPEND at
position 1
I1110 01:47:04.022734 30978 registrar.cpp:506] Successfully updated the
registry in 4.029952ms
I1110 01:47:04.022866 30976 log.cpp:596] Attempting to truncate the log to 1
I1110 01:47:04.022939 30978 registrar.cpp:392] Successfully recovered registrar
I1110 01:47:04.023027 30983 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I1110 01:47:04.023519 30969 master.cpp:1676] Recovered 0 agents from the
registry (129B); allowing 10mins for agents to re-register
I1110 01:47:04.023612 30981 hierarchical.cpp:176] Skipping recovery of
hierarchical allocator: nothing to recover
I1110 01:47:04.023897 30973 replica.cpp:537] Replica received write request for
position 2 from __req_res__(6279)@172.17.0.2:55933
I1110 01:47:04.024206 30973 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 269989ns
I1110 01:47:04.024230 30973 replica.cpp:708] Persisted action TRUNCATE at
position 2
I1110 01:47:04.024854 30973 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I1110 01:47:04.025015 30973 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 130897ns
I1110 01:47:04.025069 30973 leveldb.cpp:399] Deleting ~1 keys from leveldb took
29479ns
I1110 01:47:04.025094 30973 replica.cpp:708] Persisted action TRUNCATE at
position 2
I1110 01:47:04.028472 30949 containerizer.cpp:201] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
W1110 01:47:04.029212 30949 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges, but is running as user mesos
W1110 01:47:04.029398 30949 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
I1110 01:47:04.033748 30949 cluster.cpp:435] Creating default 'local' authorizer
I1110 01:47:04.035281 30968 slave.cpp:208] Mesos agent started on
(484)@172.17.0.2:55933
I1110 01:47:04.035302 30968 slave.cpp:209] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --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/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/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_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_command_executor="false"
--http_credentials="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/mesos/mesos-1.2.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --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/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K"
--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/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx"
I1110 01:47:04.035907 30968 credentials.hpp:86] Loading credential for
authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/credential'
I1110 01:47:04.036131 30968 slave.cpp:346] Agent using credential for:
test-principal
I1110 01:47:04.036176 30968 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/http_credentials'
I1110 01:47:04.036429 30968 http.cpp:895] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1110 01:47:04.036474 30949 sched.cpp:226] Version: 1.2.0
I1110 01:47:04.036689 30968 http.cpp:895] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1110 01:47:04.037214 30978 sched.cpp:330] New master detected at
[email protected]:55933
I1110 01:47:04.037295 30978 sched.cpp:396] Authenticating with master
[email protected]:55933
I1110 01:47:04.037315 30978 sched.cpp:403] Using default CRAM-MD5 authenticatee
I1110 01:47:04.037513 30977 authenticatee.cpp:121] Creating new client SASL
connection
I1110 01:47:04.037752 30970 master.cpp:6745] Authenticating
[email protected]:55933
I1110 01:47:04.037886 30981 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1004)@172.17.0.2:55933
I1110 01:47:04.037948 30968 slave.cpp:533] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1110 01:47:04.038069 30968 slave.cpp:541] Agent attributes: [ ]
I1110 01:47:04.038086 30968 slave.cpp:546] Agent hostname: 2aa403d92175
I1110 01:47:04.038112 30980 authenticator.cpp:98] Creating new server SASL
connection
I1110 01:47:04.038341 30979 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1110 01:47:04.038413 30979 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1110 01:47:04.038516 30979 authenticator.cpp:204] Received SASL authentication
start
I1110 01:47:04.038583 30979 authenticator.cpp:326] Authentication requires more
steps
I1110 01:47:04.038746 30975 authenticatee.cpp:259] Received SASL authentication
step
I1110 01:47:04.038915 30979 authenticator.cpp:232] Received SASL authentication
step
I1110 01:47:04.038949 30979 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '2aa403d92175' server FQDN: '2aa403d92175'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1110 01:47:04.038993 30979 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1110 01:47:04.039060 30979 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1110 01:47:04.039120 30979 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '2aa403d92175' server FQDN: '2aa403d92175'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1110 01:47:04.039230 30979 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1110 01:47:04.039327 30979 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1110 01:47:04.039376 30979 authenticator.cpp:318] Authentication success
I1110 01:47:04.039505 30978 authenticatee.cpp:299] Authentication success
I1110 01:47:04.039585 30975 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1004)@172.17.0.2:55933
I1110 01:47:04.039609 30969 master.cpp:6775] Successfully authenticated
principal 'test-principal' at
[email protected]:55933
I1110 01:47:04.039789 30983 state.cpp:57] Recovering state from
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta'
I1110 01:47:04.040001 30980 sched.cpp:502] Successfully authenticated with
master [email protected]:55933
I1110 01:47:04.040033 30980 sched.cpp:820] Sending SUBSCRIBE call to
[email protected]:55933
I1110 01:47:04.040040 30969 status_update_manager.cpp:203] Recovering status
update manager
I1110 01:47:04.040293 30980 sched.cpp:853] Will retry registration in
1.185809177secs if necessary
I1110 01:47:04.040323 30977 containerizer.cpp:557] Recovering containerizer
I1110 01:47:04.040422 30969 master.cpp:2612] Received SUBSCRIBE call for
framework 'default' at
[email protected]:55933
I1110 01:47:04.040478 30969 master.cpp:2069] Authorizing framework principal
'test-principal' to receive offers for role '*'
I1110 01:47:04.040863 30978 master.cpp:2688] Subscribing framework default with
checkpointing enabled and capabilities [ ]
I1110 01:47:04.041512 30971 sched.cpp:743] Framework registered with
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.041538 30981 hierarchical.cpp:275] Added framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.041563 30971 sched.cpp:757] Scheduler::registered took 23494ns
I1110 01:47:04.041627 30981 hierarchical.cpp:1694] No allocations performed
I1110 01:47:04.041663 30981 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:04.041735 30981 hierarchical.cpp:1286] Performed allocation for 0
agents in 163344ns
I1110 01:47:04.041880 30978 provisioner.cpp:253] Provisioner recovery complete
I1110 01:47:04.042335 30973 slave.cpp:5411] Finished recovery
I1110 01:47:04.042711 30973 slave.cpp:5585] Querying resource estimator for
oversubscribable resources
I1110 01:47:04.043046 30968 slave.cpp:915] New master detected at
[email protected]:55933
I1110 01:47:04.043072 30968 slave.cpp:974] Authenticating with master
[email protected]:55933
I1110 01:47:04.043069 30970 status_update_manager.cpp:177] Pausing sending
status updates
I1110 01:47:04.043124 30968 slave.cpp:985] Using default CRAM-MD5 authenticatee
I1110 01:47:04.043251 30968 slave.cpp:947] Detecting new master
I1110 01:47:04.043284 30969 authenticatee.cpp:121] Creating new client SASL
connection
I1110 01:47:04.043411 30968 slave.cpp:5599] Received oversubscribable resources
{} from the resource estimator
I1110 01:47:04.043546 30979 master.cpp:6745] Authenticating
slave(484)@172.17.0.2:55933
I1110 01:47:04.043647 30968 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1005)@172.17.0.2:55933
I1110 01:47:04.044533 30983 authenticator.cpp:98] Creating new server SASL
connection
I1110 01:47:04.044773 30971 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1110 01:47:04.044818 30971 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1110 01:47:04.044955 30969 authenticator.cpp:204] Received SASL authentication
start
I1110 01:47:04.045042 30969 authenticator.cpp:326] Authentication requires more
steps
I1110 01:47:04.045192 30971 authenticatee.cpp:259] Received SASL authentication
step
I1110 01:47:04.045333 30976 authenticator.cpp:232] Received SASL authentication
step
I1110 01:47:04.045400 30976 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '2aa403d92175' server FQDN: '2aa403d92175'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1110 01:47:04.045475 30976 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1110 01:47:04.045513 30976 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1110 01:47:04.045570 30976 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '2aa403d92175' server FQDN: '2aa403d92175'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1110 01:47:04.045613 30976 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1110 01:47:04.045629 30976 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1110 01:47:04.045652 30976 authenticator.cpp:318] Authentication success
I1110 01:47:04.045755 30969 authenticatee.cpp:299] Authentication success
I1110 01:47:04.045864 30977 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1005)@172.17.0.2:55933
I1110 01:47:04.046144 30972 master.cpp:6775] Successfully authenticated
principal 'test-principal' at slave(484)@172.17.0.2:55933
I1110 01:47:04.046275 30974 slave.cpp:1069] Successfully authenticated with
master [email protected]:55933
I1110 01:47:04.046475 30974 slave.cpp:1483] Will retry registration in
18.61129ms if necessary
I1110 01:47:04.046663 30970 master.cpp:5154] Registering agent at
slave(484)@172.17.0.2:55933 (2aa403d92175) with id
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.047143 30969 registrar.cpp:461] Applied 1 operations in 69780ns;
attempting to update the registry
I1110 01:47:04.047935 30972 log.cpp:577] Attempting to append 337 bytes to the
log
I1110 01:47:04.048208 30980 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I1110 01:47:04.049090 30978 replica.cpp:537] Replica received write request for
position 3 from __req_res__(6280)@172.17.0.2:55933
I1110 01:47:04.049310 30978 leveldb.cpp:341] Persisting action (356 bytes) to
leveldb took 174864ns
I1110 01:47:04.049336 30978 replica.cpp:708] Persisted action APPEND at
position 3
I1110 01:47:04.050040 30983 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I1110 01:47:04.050732 30983 leveldb.cpp:341] Persisting action (358 bytes) to
leveldb took 483627ns
I1110 01:47:04.050768 30983 replica.cpp:708] Persisted action APPEND at
position 3
I1110 01:47:04.052542 30980 registrar.cpp:506] Successfully updated the
registry in 5.315072ms
I1110 01:47:04.052901 30982 log.cpp:596] Attempting to truncate the log to 3
I1110 01:47:04.053048 30969 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I1110 01:47:04.053823 30975 replica.cpp:537] Replica received write request for
position 4 from __req_res__(6281)@172.17.0.2:55933
I1110 01:47:04.053972 30982 slave.cpp:4263] Received ping from
slave-observer(468)@172.17.0.2:55933
I1110 01:47:04.053988 30971 master.cpp:5225] Registered agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1110 01:47:04.054131 30982 slave.cpp:1115] Registered with master
[email protected]:55933; given agent ID 0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.054157 30982 fetcher.cpp:86] Clearing fetcher cache
I1110 01:47:04.054172 30975 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 294515ns
I1110 01:47:04.054196 30975 replica.cpp:708] Persisted action TRUNCATE at
position 4
I1110 01:47:04.054312 30970 status_update_manager.cpp:184] Resuming sending
status updates
I1110 01:47:04.054469 30982 slave.cpp:1138] Checkpointing SlaveInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/slave.info'
I1110 01:47:04.054462 30976 hierarchical.cpp:485] Added agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 (2aa403d92175) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I1110 01:47:04.054819 30975 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I1110 01:47:04.054824 30982 slave.cpp:1175] Forwarding total oversubscribed
resources {}
I1110 01:47:04.054996 30975 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 142626ns
I1110 01:47:04.054997 30982 master.cpp:5624] Received update of agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175) with total oversubscribed resources {}
I1110 01:47:04.055069 30975 leveldb.cpp:399] Deleting ~2 keys from leveldb took
45108ns
I1110 01:47:04.055097 30975 replica.cpp:708] Persisted action TRUNCATE at
position 4
I1110 01:47:04.055635 30976 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:04.055712 30976 hierarchical.cpp:1309] Performed allocation for
agent 0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 in 1.181697ms
I1110 01:47:04.055929 30976 hierarchical.cpp:555] Agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 (2aa403d92175) updated with
oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I1110 01:47:04.056046 30976 hierarchical.cpp:1694] No allocations performed
I1110 01:47:04.056083 30976 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:04.056138 30976 hierarchical.cpp:1309] Performed allocation for
agent 0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 in 166856ns
I1110 01:47:04.056236 30983 master.cpp:6574] Sending 1 offers to framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933
I1110 01:47:04.056737 30968 sched.cpp:917] Scheduler::resourceOffers took
99518ns
I1110 01:47:04.058730 30972 master.cpp:3581] Processing ACCEPT call for offers:
[ 0c3821c4-3478-4e0b-8621-6ed22c08bdda-O0 ] on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175) for framework 0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
(default) at [email protected]:55933
I1110 01:47:04.058835 30972 master.cpp:3173] Authorizing framework principal
'test-principal' to launch task 902045a3-632f-4ac0-b87e-c58e00754ae2
I1110 01:47:04.060703 30972 master.cpp:8337] Adding task
902045a3-632f-4ac0-b87e-c58e00754ae2 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 (2aa403d92175)
I1110 01:47:04.060982 30972 master.cpp:4233] Launching task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.063133 30969 slave.cpp:1547] Got assigned task
'902045a3-632f-4ac0-b87e-c58e00754ae2' for framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.063272 30969 slave.cpp:6233] Checkpointing FrameworkInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/framework.info'
I1110 01:47:04.063618 30969 slave.cpp:6244] Checkpointing framework pid
'@0.0.0.0:0' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/framework.pid'
I1110 01:47:04.064317 30969 slave.cpp:1709] Launching task
'902045a3-632f-4ac0-b87e-c58e00754ae2' for framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.064853 30969 paths.cpp:530] Trying to chown
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046'
to user 'mesos'
I1110 01:47:04.071557 30969 slave.cpp:6712] Checkpointing ExecutorInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/executor.info'
I1110 01:47:04.072465 30969 slave.cpp:6319] Launching executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046'
I1110 01:47:04.073338 30976 containerizer.cpp:940] Starting container
f56e44b5-a737-491d-adbd-493e33401046 for executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.073433 30969 slave.cpp:6735] Checkpointing TaskInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046/tasks/902045a3-632f-4ac0-b87e-c58e00754ae2/task.info'
I1110 01:47:04.074141 30969 slave.cpp:2031] Queued task
'902045a3-632f-4ac0-b87e-c58e00754ae2' for executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.074265 30969 slave.cpp:868] Successfully attached file
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046'
I1110 01:47:04.077942 30974 containerizer.cpp:1480] Launching
'mesos-containerizer' with flags
'--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.2.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.2.0\/_build\/src\/mesos-executor"}"
--help="false" --pipe_read="23" --pipe_write="28" --pre_exec_commands="[]"
--runtime_directory="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/containers/f56e44b5-a737-491d-adbd-493e33401046"
--unshare_namespace_mnt="false" --user="mesos"
--working_directory="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046"'
I1110 01:47:04.080380 30974 launcher.cpp:127] Forked child with pid '9773' for
container 'f56e44b5-a737-491d-adbd-493e33401046'
I1110 01:47:04.080814 30974 containerizer.cpp:1517] Checkpointing container's
forked pid 9773 to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046/pids/forked.pid'
I1110 01:47:04.083344 30982 fetcher.cpp:345] Starting to fetch URIs for
container: f56e44b5-a737-491d-adbd-493e33401046, directory:
/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046
I1110 01:47:04.266027 9814 exec.cpp:162] Version: 1.2.0
I1110 01:47:04.269335 30973 slave.cpp:3305] Got registration for executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from executor(1)@172.17.0.2:59627
I1110 01:47:04.270231 30973 slave.cpp:3391] Checkpointing executor pid
'executor(1)@172.17.0.2:59627' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046/pids/libprocess.pid'
I1110 01:47:04.271877 9814 exec.cpp:237] Executor registered on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.272480 30977 slave.cpp:2247] Sending queued task
'902045a3-632f-4ac0-b87e-c58e00754ae2' to executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 at executor(1)@172.17.0.2:59627
Received SUBSCRIBED event
Subscribed executor on 2aa403d92175
Received LAUNCH event
Starting task 902045a3-632f-4ac0-b87e-c58e00754ae2
/mesos/mesos-1.2.0/_build/src/mesos-containerizer launch
--command="{"shell":true,"value":"sleep 1000"}" --help="false"
--unshare_namespace_mnt="false"
Forked command at 9818
I1110 01:47:04.282410 30973 slave.cpp:3740] Handling status update TASK_RUNNING
(UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from executor(1)@172.17.0.2:59627
I1110 01:47:04.284265 30978 status_update_manager.cpp:323] Received status
update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.284343 30978 status_update_manager.cpp:500] Creating
StatusUpdate stream for task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.284904 30978 status_update_manager.cpp:832] Checkpointing UPDATE
for status update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for
task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.285187 30978 status_update_manager.cpp:377] Forwarding update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to the agent
I1110 01:47:04.285516 30975 slave.cpp:4181] Forwarding the update TASK_RUNNING
(UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to [email protected]:55933
I1110 01:47:04.285845 30975 slave.cpp:4075] Status update manager successfully
handled status update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392)
for task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.285907 30975 slave.cpp:4091] Sending acknowledgement for status
update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to executor(1)@172.17.0.2:59627
I1110 01:47:04.285959 30980 master.cpp:5760] Status update TASK_RUNNING (UUID:
b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.286026 30980 master.cpp:5822] Forwarding status update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.286218 30980 master.cpp:7715] Updating the state of task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I1110 01:47:04.286448 30983 sched.cpp:1025] Scheduler::statusUpdate took
120774ns
I1110 01:47:04.286926 30974 master.cpp:4870] Processing ACKNOWLEDGE call
b92b2c31-f52c-4158-a6c3-fd53f855e392 for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.286964 30978 slave.cpp:787] Agent terminating
I1110 01:47:04.287338 30974 master.cpp:1258] Agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175) disconnected
I1110 01:47:04.287369 30974 master.cpp:2977] Disconnecting agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.287469 30974 master.cpp:2996] Deactivating agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.287633 30949 containerizer.cpp:201] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
I1110 01:47:04.287642 30969 hierarchical.cpp:584] Agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 deactivated
W1110 01:47:04.288424 30949 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges, but is running as user mesos
W1110 01:47:04.288607 30949 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
I1110 01:47:04.296345 30949 cluster.cpp:435] Creating default 'local' authorizer
I1110 01:47:04.298619 30981 slave.cpp:208] Mesos agent started on
(485)@172.17.0.2:55933
I1110 01:47:04.298645 30981 slave.cpp:209] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --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/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/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_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_command_executor="false"
--http_credentials="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/mesos/mesos-1.2.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --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/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K"
--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/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx"
I1110 01:47:04.299587 30981 credentials.hpp:86] Loading credential for
authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/credential'
I1110 01:47:04.299918 30981 slave.cpp:346] Agent using credential for:
test-principal
I1110 01:47:04.299959 30981 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_FRXK3K/http_credentials'
I1110 01:47:04.300437 30981 http.cpp:895] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1110 01:47:04.300720 30981 http.cpp:895] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1110 01:47:04.302526 30981 slave.cpp:533] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1110 01:47:04.302652 30981 slave.cpp:541] Agent attributes: [ ]
I1110 01:47:04.302675 30981 slave.cpp:546] Agent hostname: 2aa403d92175
I1110 01:47:04.304281 30975 state.cpp:57] Recovering state from
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta'
I1110 01:47:04.304359 30975 state.cpp:698] No committed checkpointed resources
found at
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/resources/resources.info'
I1110 01:47:04.309572 30979 fetcher.cpp:86] Clearing fetcher cache
I1110 01:47:04.309664 30979 slave.cpp:5499] Recovering framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.309790 30979 slave.cpp:6469] Recovering executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.310797 30983 status_update_manager.cpp:203] Recovering status
update manager
I1110 01:47:04.310842 30983 status_update_manager.cpp:211] Recovering executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.310984 30983 status_update_manager.cpp:500] Creating
StatusUpdate stream for task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.311520 30983 status_update_manager.cpp:808] Replaying status
update stream for task 902045a3-632f-4ac0-b87e-c58e00754ae2
I1110 01:47:04.312235 30980 containerizer.cpp:557] Recovering containerizer
I1110 01:47:04.312330 30980 containerizer.cpp:613] Recovering container
f56e44b5-a737-491d-adbd-493e33401046 for executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.315170 30979 provisioner.cpp:253] Provisioner recovery complete
I1110 01:47:04.316128 30976 slave.cpp:5351] Sending reconnect request to
executor '902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 at executor(1)@172.17.0.2:59627
I1110 01:47:04.316951 9813 exec.cpp:283] Received reconnect request from agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.316999 30976 slave.cpp:3670] Cleaning up un-reregistered
executors
I1110 01:47:04.317028 30976 slave.cpp:3688] Killing un-reregistered executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 at executor(1)@172.17.0.2:59627
I1110 01:47:04.317075 30974 hierarchical.cpp:1694] No allocations performed
I1110 01:47:04.317198 30974 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:04.317263 30974 hierarchical.cpp:1286] Performed allocation for 1
agents in 321758ns
I1110 01:47:04.317276 30973 containerizer.cpp:1973] Destroying container
f56e44b5-a737-491d-adbd-493e33401046 in RUNNING state
I1110 01:47:04.317337 30976 slave.cpp:5411] Finished recovery
I1110 01:47:04.317567 30973 launcher.cpp:143] Asked to destroy container
f56e44b5-a737-491d-adbd-493e33401046
I1110 01:47:04.318305 30976 slave.cpp:5585] Querying resource estimator for
oversubscribable resources
W1110 01:47:04.318573 30976 slave.cpp:3488] Shutting down executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 because the agent is not in recovery
mode
I1110 01:47:04.318987 30976 slave.cpp:915] New master detected at
[email protected]:55933
I1110 01:47:04.319015 30976 slave.cpp:974] Authenticating with master
[email protected]:55933
I1110 01:47:04.319056 30972 status_update_manager.cpp:177] Pausing sending
status updates
I1110 01:47:04.319126 9803 exec.cpp:414] Executor asked to shutdown
I1110 01:47:04.319139 30976 slave.cpp:985] Using default CRAM-MD5 authenticatee
I1110 01:47:04.319322 30976 slave.cpp:947] Detecting new master
I1110 01:47:04.319439 30968 authenticatee.cpp:121] Creating new client SASL
connection
Received SHUTDOWN event
Shutting down
I1110 01:47:04.319599 30976 slave.cpp:5599] Received oversubscribable resources
{} from the resource estimator
Sending SIGTERM to process tree at pid 9818
I1110 01:47:04.319726 30968 master.cpp:6745] Authenticating
slave(485)@172.17.0.2:55933
I1110 01:47:04.319896 30970 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1006)@172.17.0.2:55933
I1110 01:47:04.320173 30975 authenticator.cpp:98] Creating new server SASL
connection
I1110 01:47:04.320425 30978 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1110 01:47:04.320453 30978 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1110 01:47:04.320571 30974 authenticator.cpp:204] Received SASL authentication
start
I1110 01:47:04.320632 30974 authenticator.cpp:326] Authentication requires more
steps
I1110 01:47:04.320730 30974 authenticatee.cpp:259] Received SASL authentication
step
I1110 01:47:04.320915 30976 authenticator.cpp:232] Received SASL authentication
step
I1110 01:47:04.320961 30976 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '2aa403d92175' server FQDN: '2aa403d92175'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1110 01:47:04.320988 30976 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1110 01:47:04.321045 30976 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1110 01:47:04.321086 30976 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '2aa403d92175' server FQDN: '2aa403d92175'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1110 01:47:04.321110 30976 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1110 01:47:04.321127 30976 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1110 01:47:04.321157 30976 authenticator.cpp:318] Authentication success
I1110 01:47:04.321281 30969 authenticatee.cpp:299] Authentication success
I1110 01:47:04.321353 30979 master.cpp:6775] Successfully authenticated
principal 'test-principal' at slave(485)@172.17.0.2:55933
I1110 01:47:04.321400 30969 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1006)@172.17.0.2:55933
I1110 01:47:04.321717 30970 slave.cpp:1069] Successfully authenticated with
master [email protected]:55933
I1110 01:47:04.322115 30970 slave.cpp:1483] Will retry registration in 40523ns
if necessary
I1110 01:47:04.322487 30980 master.cpp:5304] Re-registering agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(484)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.322726 30976 slave.cpp:1483] Will retry registration in
30.654854ms if necessary
I1110 01:47:04.322947 30980 master.cpp:5563] Sending updated checkpointed
resources {} to agent 0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at
slave(485)@172.17.0.2:55933 (2aa403d92175)
I1110 01:47:04.323081 30976 slave.cpp:1217] Re-registered with master
[email protected]:55933
I1110 01:47:04.323091 30975 hierarchical.cpp:572] Agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 reactivated
I1110 01:47:04.323333 30976 slave.cpp:1253] Forwarding total oversubscribed
resources {}
I1110 01:47:04.323503 30982 status_update_manager.cpp:184] Resuming sending
status updates
I1110 01:47:04.323675 30980 master.cpp:5304] Re-registering agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175)
W1110 01:47:04.323706 30982 status_update_manager.cpp:191] Resending status
update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.323799 30976 slave.cpp:2807] Ignoring new checkpointed resources
identical to the current version: {}
I1110 01:47:04.324000 30982 status_update_manager.cpp:377] Forwarding update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to the agent
I1110 01:47:04.324232 30980 master.cpp:5563] Sending updated checkpointed
resources {} to agent 0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at
slave(485)@172.17.0.2:55933 (2aa403d92175)
I1110 01:47:04.324347 30974 slave.cpp:2744] Updating framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 pid to @0.0.0.0:0
I1110 01:47:04.324411 30980 master.cpp:5624] Received update of agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175) with total oversubscribed resources {}
I1110 01:47:04.324596 30974 slave.cpp:2760] Checkpointing framework pid
'@0.0.0.0:0' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/framework.pid'
I1110 01:47:04.324724 30982 hierarchical.cpp:555] Agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 (2aa403d92175) updated with
oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I1110 01:47:04.324899 30982 hierarchical.cpp:1694] No allocations performed
I1110 01:47:04.324942 30982 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:04.325055 30982 hierarchical.cpp:1309] Performed allocation for
agent 0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 in 264164ns
I1110 01:47:04.325191 30978 status_update_manager.cpp:184] Resuming sending
status updates
W1110 01:47:04.325192 30974 slave.cpp:1234] Already re-registered with master
[email protected]:55933
W1110 01:47:04.325232 30978 status_update_manager.cpp:191] Resending status
update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.325256 30974 slave.cpp:1253] Forwarding total oversubscribed
resources {}
I1110 01:47:04.325284 30978 status_update_manager.cpp:377] Forwarding update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to the agent
I1110 01:47:04.325417 30974 slave.cpp:2744] Updating framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 pid to
[email protected]:55933
I1110 01:47:04.325451 30975 master.cpp:5624] Received update of agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175) with total oversubscribed resources {}
I1110 01:47:04.325655 30974 slave.cpp:2760] Checkpointing framework pid
'[email protected]:55933' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/framework.pid'
I1110 01:47:04.325789 30975 hierarchical.cpp:555] Agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 (2aa403d92175) updated with
oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I1110 01:47:04.325958 30975 hierarchical.cpp:1694] No allocations performed
I1110 01:47:04.325999 30975 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:04.326052 30975 hierarchical.cpp:1309] Performed allocation for
agent 0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 in 184759ns
I1110 01:47:04.326104 30974 slave.cpp:2807] Ignoring new checkpointed resources
identical to the current version: {}
I1110 01:47:04.326148 30979 status_update_manager.cpp:184] Resuming sending
status updates
W1110 01:47:04.326203 30979 status_update_manager.cpp:191] Resending status
update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.326288 30974 slave.cpp:4181] Forwarding the update TASK_RUNNING
(UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to [email protected]:55933
I1110 01:47:04.326402 30979 status_update_manager.cpp:377] Forwarding update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to the agent
I1110 01:47:04.326719 30975 master.cpp:5760] Status update TASK_RUNNING (UUID:
b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.326745 30974 slave.cpp:4249] Sending message for framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to
[email protected]:55933
I1110 01:47:04.326783 30975 master.cpp:5822] Forwarding status update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.326958 30978 sched.cpp:1161] Scheduler::frameworkMessage took
34582ns
I1110 01:47:04.326982 30975 master.cpp:7715] Updating the state of task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I1110 01:47:04.326967 30974 slave.cpp:4181] Forwarding the update TASK_RUNNING
(UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to [email protected]:55933
I1110 01:47:04.327183 30978 sched.cpp:1025] Scheduler::statusUpdate took 27296ns
I1110 01:47:04.327325 30974 slave.cpp:4181] Forwarding the update TASK_RUNNING
(UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to [email protected]:55933
I1110 01:47:04.327560 30979 master.cpp:5760] Status update TASK_RUNNING (UUID:
b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.327615 30979 master.cpp:5822] Forwarding status update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.327985 30979 master.cpp:7715] Updating the state of task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I1110 01:47:04.328109 30977 sched.cpp:1025] Scheduler::statusUpdate took 39969ns
I1110 01:47:04.328541 30979 master.cpp:4870] Processing ACKNOWLEDGE call
b92b2c31-f52c-4158-a6c3-fd53f855e392 for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.328848 30969 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.328874 30979 master.cpp:5760] Status update TASK_RUNNING (UUID:
b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.329010 30969 status_update_manager.cpp:832] Checkpointing ACK
for status update TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for
task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.329051 30979 master.cpp:5822] Forwarding status update
TASK_RUNNING (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.329288 30979 master.cpp:7715] Updating the state of task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I1110 01:47:04.329320 30969 slave.cpp:3022] Status update manager successfully
handled status update acknowledgement (UUID:
b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.329428 30982 sched.cpp:1025] Scheduler::statusUpdate took 17098ns
I1110 01:47:04.329438 30979 master.cpp:4870] Processing ACKNOWLEDGE call
b92b2c31-f52c-4158-a6c3-fd53f855e392 for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.330005 30983 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.330072 30979 master.cpp:4870] Processing ACKNOWLEDGE call
b92b2c31-f52c-4158-a6c3-fd53f855e392 for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
E1110 01:47:04.330207 30970 slave.cpp:3015] Failed to handle status update
acknowledgement (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000: Unexpected status update
acknowledgment (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.330404 30983 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
E1110 01:47:04.330606 30968 slave.cpp:3015] Failed to handle status update
acknowledgement (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000: Unexpected status update
acknowledgment (UUID: b92b2c31-f52c-4158-a6c3-fd53f855e392) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.418934 30980 containerizer.cpp:2336] Container
f56e44b5-a737-491d-adbd-493e33401046 has exited
I1110 01:47:04.421025 30973 provisioner.cpp:324] Ignoring destroy request for
unknown container f56e44b5-a737-491d-adbd-493e33401046
I1110 01:47:04.421566 30971 slave.cpp:4672] Executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 terminated with signal Killed
I1110 01:47:04.421744 30971 slave.cpp:3740] Handling status update TASK_LOST
(UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from @0.0.0.0:0
W1110 01:47:04.422590 30983 containerizer.cpp:1788] Ignoring update for unknown
container f56e44b5-a737-491d-adbd-493e33401046
I1110 01:47:04.422958 30969 status_update_manager.cpp:323] Received status
update TASK_LOST (UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.423032 30969 status_update_manager.cpp:832] Checkpointing UPDATE
for status update TASK_LOST (UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for
task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.423251 30969 status_update_manager.cpp:377] Forwarding update
TASK_LOST (UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to the agent
I1110 01:47:04.423480 30983 slave.cpp:4181] Forwarding the update TASK_LOST
(UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 to [email protected]:55933
I1110 01:47:04.423681 30983 slave.cpp:4075] Status update manager successfully
handled status update TASK_LOST (UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948)
for task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.423841 30974 master.cpp:5760] Status update TASK_LOST (UUID:
0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 from agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.423903 30974 master.cpp:5822] Forwarding status update TASK_LOST
(UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.424094 30974 master.cpp:7715] Updating the state of task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (latest state: TASK_LOST, status
update state: TASK_LOST)
I1110 01:47:04.424212 30980 sched.cpp:1025] Scheduler::statusUpdate took 25391ns
I1110 01:47:04.424965 30974 master.cpp:4870] Processing ACKNOWLEDGE call
0980f7f0-ab68-4e75-b855-3a3d15e13948 for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:04.425037 30974 master.cpp:7811] Removing task
902045a3-632f-4ac0-b87e-c58e00754ae2 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 at slave(485)@172.17.0.2:55933
(2aa403d92175)
I1110 01:47:04.425376 30978 hierarchical.cpp:1018] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 from framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.425662 30982 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.425781 30982 status_update_manager.cpp:832] Checkpointing ACK
for status update TASK_LOST (UUID: 0980f7f0-ab68-4e75-b855-3a3d15e13948) for
task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.425892 30982 status_update_manager.cpp:531] Cleaning up status
update stream for task 902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.426255 30968 slave.cpp:3022] Status update manager successfully
handled status update acknowledgement (UUID:
0980f7f0-ab68-4e75-b855-3a3d15e13948) for task
902045a3-632f-4ac0-b87e-c58e00754ae2 of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.426304 30968 slave.cpp:6691] Completing task
902045a3-632f-4ac0-b87e-c58e00754ae2
I1110 01:47:04.426339 30968 slave.cpp:4776] Cleaning up executor
'902045a3-632f-4ac0-b87e-c58e00754ae2' of framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 at executor(1)@172.17.0.2:59627
I1110 01:47:04.426758 30974 gc.cpp:55] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046'
for gc 6.99999506167704days in the future
I1110 01:47:04.427039 30974 gc.cpp:55] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2'
for gc 6.99999505936296days in the future
I1110 01:47:04.427217 30968 slave.cpp:4864] Cleaning up framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.427232 30974 gc.cpp:55] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2/runs/f56e44b5-a737-491d-adbd-493e33401046'
for gc 6.99999505757037days in the future
I1110 01:47:04.427347 30982 status_update_manager.cpp:285] Closing status
update streams for framework 0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:04.427369 30974 gc.cpp:55] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000/executors/902045a3-632f-4ac0-b87e-c58e00754ae2'
for gc 6.99999505615704days in the future
I1110 01:47:04.427522 30974 gc.cpp:55] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000'
for gc 6.9999950534963days in the future
I1110 01:47:04.427646 30974 gc.cpp:55] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_SchOhx/meta/slaves/0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0/frameworks/0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000'
for gc 6.99999505233778days in the future
I1110 01:47:05.319938 30973 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:05.320070 30973 hierarchical.cpp:1286] Performed allocation for 1
agents in 2.304896ms
I1110 01:47:05.320617 30980 master.cpp:6574] Sending 1 offers to framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933
I1110 01:47:05.321238 30969 sched.cpp:917] Scheduler::resourceOffers took
20712ns
I1110 01:47:06.321573 30978 hierarchical.cpp:1694] No allocations performed
I1110 01:47:06.321661 30978 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:06.321750 30978 hierarchical.cpp:1286] Performed allocation for 1
agents in 460520ns
I1110 01:47:07.322912 30983 hierarchical.cpp:1694] No allocations performed
I1110 01:47:07.322999 30983 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:07.323097 30983 hierarchical.cpp:1286] Performed allocation for 1
agents in 489403ns
I1110 01:47:08.324069 30977 hierarchical.cpp:1694] No allocations performed
I1110 01:47:08.324156 30977 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:08.324259 30977 hierarchical.cpp:1286] Performed allocation for 1
agents in 456027ns
I1110 01:47:09.325582 30971 hierarchical.cpp:1694] No allocations performed
I1110 01:47:09.325664 30971 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:09.325752 30971 hierarchical.cpp:1286] Performed allocation for 1
agents in 406560ns
I1110 01:47:10.326511 30968 hierarchical.cpp:1694] No allocations performed
I1110 01:47:10.326606 30968 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:10.326707 30968 hierarchical.cpp:1286] Performed allocation for 1
agents in 473891ns
I1110 01:47:11.327615 30982 hierarchical.cpp:1694] No allocations performed
I1110 01:47:11.327704 30982 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:11.327795 30982 hierarchical.cpp:1286] Performed allocation for 1
agents in 435260ns
I1110 01:47:12.328523 30983 hierarchical.cpp:1694] No allocations performed
I1110 01:47:12.328613 30983 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:12.328701 30983 hierarchical.cpp:1286] Performed allocation for 1
agents in 397924ns
I1110 01:47:13.329785 30973 hierarchical.cpp:1694] No allocations performed
I1110 01:47:13.330016 30973 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:13.330094 30973 hierarchical.cpp:1286] Performed allocation for 1
agents in 515417ns
I1110 01:47:14.331346 30970 hierarchical.cpp:1694] No allocations performed
I1110 01:47:14.331434 30970 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:14.331522 30970 hierarchical.cpp:1286] Performed allocation for 1
agents in 456719ns
I1110 01:47:15.332098 30979 hierarchical.cpp:1694] No allocations performed
I1110 01:47:15.332175 30979 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:15.332267 30979 hierarchical.cpp:1286] Performed allocation for 1
agents in 387115ns
I1110 01:47:16.333844 30972 hierarchical.cpp:1694] No allocations performed
I1110 01:47:16.333933 30972 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:16.334027 30972 hierarchical.cpp:1286] Performed allocation for 1
agents in 461037ns
I1110 01:47:17.334760 30974 hierarchical.cpp:1694] No allocations performed
I1110 01:47:17.334843 30974 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:17.334957 30974 hierarchical.cpp:1286] Performed allocation for 1
agents in 478871ns
I1110 01:47:18.336357 30982 hierarchical.cpp:1694] No allocations performed
I1110 01:47:18.336462 30982 hierarchical.cpp:1789] No inverse offers to send
out!
I1110 01:47:18.336591 30982 hierarchical.cpp:1286] Performed allocation for 1
agents in 567921ns
I1110 01:47:19.320394 30980 slave.cpp:5585] Querying resource estimator for
oversubscribable resources
I1110 01:47:19.320847 30968 slave.cpp:5599] Received oversubscribable resources
{} from the resource estimator
../../src/tests/slave_tests.cpp:4760: Failure
Failed to wait 15secs for executorToFrameworkMessage1
I1110 01:47:19.326982 30975 master.cpp:1297] Framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 disconnected
I1110 01:47:19.327041 30975 master.cpp:2918] Disconnecting framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933
I1110 01:47:19.327098 30975 master.cpp:2942] Deactivating framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933
W1110 01:47:19.327787 30975 master.hpp:2264] Master attempted to send message
to disconnected framework 0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default)
at [email protected]:55933
I1110 01:47:19.327900 30975 master.cpp:1310] Giving framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933 0ns to failover
I1110 01:47:19.327970 30972 hierarchical.cpp:386] Deactivated framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:19.328275 30976 master.cpp:6426] Framework failover timeout,
removing framework 0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933
I1110 01:47:19.328315 30976 master.cpp:7170] Removing framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 (default) at
[email protected]:55933
I1110 01:47:19.328508 30978 slave.cpp:2575] Asked to shut down framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000 by [email protected]:55933
I1110 01:47:19.328542 30978 slave.cpp:2590] Cannot shut down unknown framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:19.329155 30978 slave.cpp:787] Agent terminating
I1110 01:47:19.329264 30972 hierarchical.cpp:1018] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0 from framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:19.329473 30972 hierarchical.cpp:337] Removed framework
0c3821c4-3478-4e0b-8621-6ed22c08bdda-0000
I1110 01:47:19.335469 30968 master.cpp:1097] Master terminating
I1110 01:47:19.336614 30970 hierarchical.cpp:517] Removed agent
0c3821c4-3478-4e0b-8621-6ed22c08bdda-S0
I1110 01:47:19.337482 30975 hierarchical.cpp:1694] No allocations performed
I1110 01:47:19.337574 30975 hierarchical.cpp:1286] Performed allocation for 0
agents in 165749ns
../../3rdparty/libprocess/include/process/gmock.hpp:446: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock,
filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <28-C6 03-D4 FC-2A 00-00>, 1,
1)
Expected: to be called once
Actual: never called - unsatisfied and active
../../3rdparty/libprocess/include/process/gmock.hpp:446: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock,
filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <28-C6 03-D4 FC-2A 00-00>, 1,
1-byte object <58>)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] SlaveTest.HTTPSchedulerSlaveRestart (15350 ms)
{noformat}
> SlaveTest.HTTPSchedulerSlaveRestart is flaky
> --------------------------------------------
>
> Key: MESOS-4404
> URL: https://issues.apache.org/jira/browse/MESOS-4404
> Project: Mesos
> Issue Type: Bug
> Components: HTTP API, slave
> Affects Versions: 0.26.0
> Environment: From the Jenkins CI: gcc,--verbose --enable-libevent
> --enable-ssl,centos:7,docker
> Reporter: Greg Mann
> Assignee: Jian Qiu
> Labels: flaky-test, mesosphere
>
> Saw this failure on the Jenkins CI:
> {code}
> [ RUN ] SlaveTest.HTTPSchedulerSlaveRestart
> I0115 18:42:25.393354 1762 leveldb.cpp:174] Opened db in 3.456169ms
> I0115 18:42:25.394310 1762 leveldb.cpp:181] Compacted db in 922588ns
> I0115 18:42:25.394361 1762 leveldb.cpp:196] Created db iterator in 18529ns
> I0115 18:42:25.394378 1762 leveldb.cpp:202] Seeked to beginning of db in
> 1933ns
> I0115 18:42:25.394390 1762 leveldb.cpp:271] Iterated through 0 keys in the
> db in 280ns
> I0115 18:42:25.394430 1762 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0115 18:42:25.394963 1791 recover.cpp:447] Starting replica recovery
> I0115 18:42:25.395396 1791 recover.cpp:473] Replica is in EMPTY status
> I0115 18:42:25.396589 1795 replica.cpp:673] Replica in EMPTY status received
> a broadcasted recover request from (11302)@172.17.0.2:49129
> I0115 18:42:25.397101 1785 recover.cpp:193] Received a recover response from
> a replica in EMPTY status
> I0115 18:42:25.397721 1791 recover.cpp:564] Updating replica status to
> STARTING
> I0115 18:42:25.398764 1789 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 684584ns
> I0115 18:42:25.398807 1789 replica.cpp:320] Persisted replica status to
> STARTING
> I0115 18:42:25.398947 1795 master.cpp:374] Master
> 544823be-76b5-47be-b326-2cd6d6a700b8 (e648fe109cb1) started on
> 172.17.0.2:49129
> I0115 18:42:25.399209 1788 recover.cpp:473] Replica is in STARTING status
> I0115 18:42:25.398980 1795 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/BOGaaq/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --http_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="25secs" --registry_strict="true"
> --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui"
> --work_dir="/tmp/BOGaaq/master" --zk_session_timeout="10secs"
> I0115 18:42:25.399435 1795 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0115 18:42:25.399451 1795 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0115 18:42:25.399461 1795 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/BOGaaq/credentials'
> I0115 18:42:25.399884 1795 master.cpp:466] Using default 'crammd5'
> authenticator
> I0115 18:42:25.400060 1795 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0115 18:42:25.400254 1795 master.cpp:569] Authorization enabled
> I0115 18:42:25.400439 1785 hierarchical.cpp:147] Initialized hierarchical
> allocator process
> I0115 18:42:25.400470 1789 whitelist_watcher.cpp:77] No whitelist given
> I0115 18:42:25.400656 1792 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (11303)@172.17.0.2:49129
> I0115 18:42:25.400943 1781 recover.cpp:193] Received a recover response from
> a replica in STARTING status
> I0115 18:42:25.401612 1791 recover.cpp:564] Updating replica status to VOTING
> I0115 18:42:25.402313 1785 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 458849ns
> I0115 18:42:25.402345 1785 replica.cpp:320] Persisted replica status to
> VOTING
> I0115 18:42:25.402510 1788 recover.cpp:578] Successfully joined the Paxos
> group
> I0115 18:42:25.402848 1788 recover.cpp:462] Recover process terminated
> I0115 18:42:25.402997 1784 master.cpp:1710] The newly elected leader is
> [email protected]:49129 with id 544823be-76b5-47be-b326-2cd6d6a700b8
> I0115 18:42:25.403038 1784 master.cpp:1723] Elected as the leading master!
> I0115 18:42:25.403059 1784 master.cpp:1468] Recovering from registrar
> I0115 18:42:25.403267 1791 registrar.cpp:307] Recovering registrar
> I0115 18:42:25.404359 1794 log.cpp:659] Attempting to start the writer
> I0115 18:42:25.405777 1793 replica.cpp:493] Replica received implicit
> promise request from (11305)@172.17.0.2:49129 with proposal 1
> I0115 18:42:25.406337 1793 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 447531ns
> I0115 18:42:25.406366 1793 replica.cpp:342] Persisted promised to 1
> I0115 18:42:25.407235 1782 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0115 18:42:25.408753 1796 replica.cpp:388] Replica received explicit
> promise request from (11306)@172.17.0.2:49129 for position 0 with proposal 2
> I0115 18:42:25.409217 1796 leveldb.cpp:341] Persisting action (8 bytes) to
> leveldb took 411390ns
> I0115 18:42:25.409248 1796 replica.cpp:712] Persisted action at 0
> I0115 18:42:25.410698 1787 replica.cpp:537] Replica received write request
> for position 0 from (11307)@172.17.0.2:49129
> I0115 18:42:25.410768 1787 leveldb.cpp:436] Reading position from leveldb
> took 30399ns
> I0115 18:42:25.411203 1787 leveldb.cpp:341] Persisting action (14 bytes) to
> leveldb took 390465ns
> I0115 18:42:25.411233 1787 replica.cpp:712] Persisted action at 0
> I0115 18:42:25.411984 1796 replica.cpp:691] Replica received learned notice
> for position 0 from @0.0.0.0:0
> I0115 18:42:25.412431 1796 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 401825ns
> I0115 18:42:25.412464 1796 replica.cpp:712] Persisted action at 0
> I0115 18:42:25.412494 1796 replica.cpp:697] Replica learned NOP action at
> position 0
> I0115 18:42:25.413146 1789 log.cpp:675] Writer started with ending position 0
> I0115 18:42:25.414281 1781 leveldb.cpp:436] Reading position from leveldb
> took 34549ns
> I0115 18:42:25.415433 1781 registrar.cpp:340] Successfully fetched the
> registry (0B) in 12.112128ms
> I0115 18:42:25.415557 1781 registrar.cpp:439] Applied 1 operations in
> 31219ns; attempting to update the 'registry'
> I0115 18:42:25.416365 1793 log.cpp:683] Attempting to append 170 bytes to
> the log
> I0115 18:42:25.416522 1796 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0115 18:42:25.417402 1784 replica.cpp:537] Replica received write request
> for position 1 from (11308)@172.17.0.2:49129
> I0115 18:42:25.417948 1784 leveldb.cpp:341] Persisting action (189 bytes) to
> leveldb took 495850ns
> I0115 18:42:25.417979 1784 replica.cpp:712] Persisted action at 1
> I0115 18:42:25.418685 1790 replica.cpp:691] Replica received learned notice
> for position 1 from @0.0.0.0:0
> I0115 18:42:25.419095 1790 leveldb.cpp:341] Persisting action (191 bytes) to
> leveldb took 368951ns
> I0115 18:42:25.419127 1790 replica.cpp:712] Persisted action at 1
> I0115 18:42:25.419149 1790 replica.cpp:697] Replica learned APPEND action at
> position 1
> I0115 18:42:25.420243 1794 registrar.cpp:484] Successfully updated the
> 'registry' in 4.612096ms
> I0115 18:42:25.420392 1794 registrar.cpp:370] Successfully recovered
> registrar
> I0115 18:42:25.420490 1789 log.cpp:702] Attempting to truncate the log to 1
> I0115 18:42:25.420765 1796 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0115 18:42:25.421044 1791 hierarchical.cpp:165] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0115 18:42:25.420999 1784 master.cpp:1520] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I0115 18:42:25.421764 1793 replica.cpp:537] Replica received write request
> for position 2 from (11309)@172.17.0.2:49129
> I0115 18:42:25.422206 1793 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 399483ns
> I0115 18:42:25.422238 1793 replica.cpp:712] Persisted action at 2
> I0115 18:42:25.422935 1796 replica.cpp:691] Replica received learned notice
> for position 2 from @0.0.0.0:0
> I0115 18:42:25.423383 1796 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 354472ns
> I0115 18:42:25.423449 1796 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 33881ns
> I0115 18:42:25.423473 1796 replica.cpp:712] Persisted action at 2
> I0115 18:42:25.423496 1796 replica.cpp:697] Replica learned TRUNCATE action
> at position 2
> I0115 18:42:25.432976 1762 containerizer.cpp:140] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> W0115 18:42:25.433629 1762 backend.cpp:48] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0115 18:42:25.437697 1786 slave.cpp:191] Slave started on
> 366)@172.17.0.2:49129
> I0115 18:42:25.437731 1786 slave.cpp:192] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --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"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --oversubscribed_resources_interval="15secs"
> --perf_duration="10secs" --perf_interval="1mins"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj"
> I0115 18:42:25.438261 1786 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential'
> I0115 18:42:25.438501 1786 slave.cpp:322] Slave using credential for:
> test-principal
> I0115 18:42:25.438727 1786 resources.cpp:482] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0115 18:42:25.439223 1786 slave.cpp:392] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0115 18:42:25.439311 1786 slave.cpp:400] Slave attributes: [ ]
> I0115 18:42:25.439324 1786 slave.cpp:405] Slave hostname: e648fe109cb1
> I0115 18:42:25.440315 1785 state.cpp:58] Recovering state from
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta'
> I0115 18:42:25.440474 1762 sched.cpp:164] Version: 0.27.0
> I0115 18:42:25.440711 1781 status_update_manager.cpp:200] Recovering status
> update manager
> I0115 18:42:25.441057 1795 containerizer.cpp:386] Recovering containerizer
> I0115 18:42:25.441139 1782 sched.cpp:268] New master detected at
> [email protected]:49129
> I0115 18:42:25.441251 1782 sched.cpp:324] Authenticating with master
> [email protected]:49129
> I0115 18:42:25.441275 1782 sched.cpp:331] Using default CRAM-MD5
> authenticatee
> I0115 18:42:25.441511 1781 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 18:42:25.441839 1782 master.cpp:5521] Authenticating
> [email protected]:49129
> I0115 18:42:25.441931 1792 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(792)@172.17.0.2:49129
> I0115 18:42:25.442155 1794 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 18:42:25.442265 1793 provisioner.cpp:245] Provisioner recovery complete
> I0115 18:42:25.442360 1795 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 18:42:25.442391 1795 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 18:42:25.442498 1788 authenticator.cpp:203] Received SASL
> authentication start
> I0115 18:42:25.442566 1788 authenticator.cpp:325] Authentication requires
> more steps
> I0115 18:42:25.442631 1783 slave.cpp:4424] Finished recovery
> I0115 18:42:25.442664 1782 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 18:42:25.442797 1782 authenticator.cpp:231] Received SASL
> authentication step
> I0115 18:42:25.442849 1782 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 18:42:25.442870 1782 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 18:42:25.442915 1782 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 18:42:25.442953 1782 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 18:42:25.442971 1782 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 18:42:25.442984 1782 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 18:42:25.443006 1782 authenticator.cpp:317] Authentication success
> I0115 18:42:25.443120 1783 slave.cpp:4596] Querying resource estimator for
> oversubscribable resources
> I0115 18:42:25.443130 1784 authenticatee.cpp:298] Authentication success
> I0115 18:42:25.443178 1796 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(792)@172.17.0.2:49129
> I0115 18:42:25.443326 1785 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> [email protected]:49129
> I0115 18:42:25.443459 1781 sched.cpp:413] Successfully authenticated with
> master [email protected]:49129
> I0115 18:42:25.443481 1781 sched.cpp:722] Sending SUBSCRIBE call to
> [email protected]:49129
> I0115 18:42:25.443490 1789 status_update_manager.cpp:174] Pausing sending
> status updates
> I0115 18:42:25.443492 1784 slave.cpp:724] New master detected at
> [email protected]:49129
> I0115 18:42:25.443559 1781 sched.cpp:755] Will retry registration in
> 959.01868ms if necessary
> I0115 18:42:25.443578 1784 slave.cpp:787] Authenticating with master
> [email protected]:49129
> I0115 18:42:25.443604 1784 slave.cpp:792] Using default CRAM-MD5
> authenticatee
> I0115 18:42:25.443645 1792 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:49129
> I0115 18:42:25.443694 1792 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0115 18:42:25.443774 1784 slave.cpp:760] Detecting new master
> I0115 18:42:25.443799 1786 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 18:42:25.443915 1790 master.cpp:2349] Subscribing framework default
> with checkpointing enabled and capabilities [ ]
> I0115 18:42:25.444027 1784 slave.cpp:4610] Received oversubscribable
> resources from the resource estimator
> I0115 18:42:25.444248 1793 hierarchical.cpp:259] Added framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.444324 1781 sched.cpp:649] Framework registered with
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.444350 1793 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:25.444353 1790 master.cpp:5521] Authenticating
> slave(366)@172.17.0.2:49129
> I0115 18:42:25.444376 1793 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:25.444393 1793 hierarchical.cpp:1075] Performed allocation for 0
> slaves in 73885ns
> I0115 18:42:25.444413 1781 sched.cpp:663] Scheduler::registered took 57859ns
> I0115 18:42:25.444445 1792 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(793)@172.17.0.2:49129
> I0115 18:42:25.444701 1793 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 18:42:25.444942 1782 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 18:42:25.444968 1782 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 18:42:25.445047 1790 authenticator.cpp:203] Received SASL
> authentication start
> I0115 18:42:25.445101 1790 authenticator.cpp:325] Authentication requires
> more steps
> I0115 18:42:25.445176 1790 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 18:42:25.445315 1793 authenticator.cpp:231] Received SASL
> authentication step
> I0115 18:42:25.445358 1793 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 18:42:25.445372 1793 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 18:42:25.445415 1793 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 18:42:25.445447 1793 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 18:42:25.445471 1793 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 18:42:25.445487 1793 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 18:42:25.445520 1793 authenticator.cpp:317] Authentication success
> I0115 18:42:25.445637 1795 authenticatee.cpp:298] Authentication success
> I0115 18:42:25.445724 1792 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(366)@172.17.0.2:49129
> I0115 18:42:25.445765 1785 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(793)@172.17.0.2:49129
> I0115 18:42:25.446068 1787 slave.cpp:855] Successfully authenticated with
> master [email protected]:49129
> I0115 18:42:25.446259 1787 slave.cpp:1249] Will retry registration in
> 9.313561ms if necessary
> I0115 18:42:25.446457 1785 master.cpp:4235] Registering slave at
> slave(366)@172.17.0.2:49129 (e648fe109cb1) with id
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.447036 1794 registrar.cpp:439] Applied 1 operations in
> 80668ns; attempting to update the 'registry'
> I0115 18:42:25.448024 1781 log.cpp:683] Attempting to append 339 bytes to
> the log
> I0115 18:42:25.448249 1794 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 3
> I0115 18:42:25.449117 1796 replica.cpp:537] Replica received write request
> for position 3 from (11323)@172.17.0.2:49129
> I0115 18:42:25.449368 1796 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 201910ns
> I0115 18:42:25.449406 1796 replica.cpp:712] Persisted action at 3
> I0115 18:42:25.450243 1787 replica.cpp:691] Replica received learned notice
> for position 3 from @0.0.0.0:0
> I0115 18:42:25.450808 1787 leveldb.cpp:341] Persisting action (360 bytes) to
> leveldb took 521012ns
> I0115 18:42:25.450858 1787 replica.cpp:712] Persisted action at 3
> I0115 18:42:25.450896 1787 replica.cpp:697] Replica learned APPEND action at
> position 3
> I0115 18:42:25.452599 1790 registrar.cpp:484] Successfully updated the
> 'registry' in 5.43488ms
> I0115 18:42:25.452968 1786 log.cpp:702] Attempting to truncate the log to 3
> I0115 18:42:25.453186 1796 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 4
> I0115 18:42:25.453496 1791 slave.cpp:3366] Received ping from
> slave-observer(352)@172.17.0.2:49129
> I0115 18:42:25.453496 1781 master.cpp:4303] Registered slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0115 18:42:25.453718 1791 slave.cpp:899] Registered with master
> [email protected]:49129; given slave ID
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.453744 1791 fetcher.cpp:81] Clearing fetcher cache
> I0115 18:42:25.453927 1796 status_update_manager.cpp:181] Resuming sending
> status updates
> I0115 18:42:25.454176 1791 slave.cpp:922] Checkpointing SlaveInfo to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/slave.info'
> I0115 18:42:25.454267 1787 hierarchical.cpp:461] Added slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0115 18:42:25.454401 1790 replica.cpp:537] Replica received write request
> for position 4 from (11324)@172.17.0.2:49129
> I0115 18:42:25.454630 1791 slave.cpp:958] Forwarding total oversubscribed
> resources
> I0115 18:42:25.454798 1791 master.cpp:4644] Received update of slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1) with total oversubscribed resources
> I0115 18:42:25.454891 1790 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 440402ns
> I0115 18:42:25.454924 1790 replica.cpp:712] Persisted action at 4
> I0115 18:42:25.455684 1784 replica.cpp:691] Replica received learned notice
> for position 4 from @0.0.0.0:0
> I0115 18:42:25.456079 1784 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 353684ns
> I0115 18:42:25.456157 1784 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 46041ns
> I0115 18:42:25.456183 1784 replica.cpp:712] Persisted action at 4
> I0115 18:42:25.456207 1784 replica.cpp:697] Replica learned TRUNCATE action
> at position 4
> I0115 18:42:25.457523 1787 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:25.457622 1787 hierarchical.cpp:1097] Performed allocation for
> slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 3.296955ms
> I0115 18:42:25.457895 1789 master.cpp:5350] Sending 1 offers to framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129
> I0115 18:42:25.458412 1793 sched.cpp:819] Scheduler::resourceOffers took
> 137897ns
> I0115 18:42:25.459161 1787 hierarchical.cpp:517] Slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0115 18:42:25.459393 1787 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:25.459455 1787 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:25.459499 1787 hierarchical.cpp:1097] Performed allocation for
> slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 269541ns
> I0115 18:42:25.460202 1793 master.cpp:3136] Processing ACCEPT call for
> offers: [ 544823be-76b5-47be-b326-2cd6d6a700b8-O0 ] on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1) for framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> (default) at [email protected]:49129
> I0115 18:42:25.460258 1793 master.cpp:2823] Authorizing framework principal
> 'test-principal' to launch task 81845273-41cb-4086-8d26-b58acd094ec7 as user
> 'mesos'
> I0115 18:42:25.462309 1793 master.hpp:176] Adding task
> 81845273-41cb-4086-8d26-b58acd094ec7 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1)
> I0115 18:42:25.462590 1793 master.cpp:3621] Launching task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.463987 1796 slave.cpp:1289] Got assigned task
> 81845273-41cb-4086-8d26-b58acd094ec7 for framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.464197 1796 slave.cpp:5130] Checkpointing FrameworkInfo to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.info'
> I0115 18:42:25.470656 1796 slave.cpp:5141] Checkpointing framework pid
> '@0.0.0.0:0' to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.pid'
> I0115 18:42:25.471065 1796 resources.cpp:482] Parsing resources as JSON
> failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0115 18:42:25.471667 1796 slave.cpp:1408] Launching task
> 81845273-41cb-4086-8d26-b58acd094ec7 for framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.471772 1796 resources.cpp:482] Parsing resources as JSON
> failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0115 18:42:25.472612 1796 paths.cpp:434] Trying to chown
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> to user 'mesos'
> I0115 18:42:25.482182 1796 slave.cpp:5579] Checkpointing ExecutorInfo to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/executor.info'
> I0115 18:42:25.483156 1796 slave.cpp:5208] Launching executor
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> I0115 18:42:25.483779 1781 containerizer.cpp:634] Starting container
> 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' for executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> '544823be-76b5-47be-b326-2cd6d6a700b8-0000'
> I0115 18:42:25.483911 1796 slave.cpp:5602] Checkpointing TaskInfo to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8/tasks/81845273-41cb-4086-8d26-b58acd094ec7/task.info'
> I0115 18:42:25.484482 1796 slave.cpp:1626] Queuing task
> '81845273-41cb-4086-8d26-b58acd094ec7' for executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.484664 1796 slave.cpp:677] Successfully attached file
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> I0115 18:42:25.490378 1795 launcher.cpp:132] Forked child with pid '9087'
> for container 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> I0115 18:42:25.490747 1795 containerizer.cpp:980] Checkpointing executor's
> forked pid 9087 to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8/pids/forked.pid'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0115 18:42:25.631392 9087 process.cpp:994] libprocess is initialized on
> 172.17.0.2:51606 for 16 cpus
> I0115 18:42:25.632158 9087 logging.cpp:172] Logging to STDERR
> I0115 18:42:25.634042 9087 exec.cpp:134] Version: 0.27.0
> I0115 18:42:25.642711 9116 exec.cpp:184] Executor started at:
> executor(1)@172.17.0.2:51606 with pid 9087
> I0115 18:42:25.645352 1788 slave.cpp:2573] Got registration for executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 from executor(1)@172.17.0.2:51606
> I0115 18:42:25.646114 1788 slave.cpp:2659] Checkpointing executor pid
> 'executor(1)@172.17.0.2:51606' to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8/pids/libprocess.pid'
> I0115 18:42:25.648432 9114 exec.cpp:208] Executor registered on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.648674 1790 slave.cpp:1791] Sending queued task
> '81845273-41cb-4086-8d26-b58acd094ec7' to executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
> I0115 18:42:25.650701 9114 exec.cpp:220] Executor::registered took 222804ns
> Registered executor on e648fe109cb1
> I0115 18:42:25.651016 9114 exec.cpp:295] Executor asked to run task
> '81845273-41cb-4086-8d26-b58acd094ec7'
> I0115 18:42:25.651127 9114 exec.cpp:304] Executor::launchTask took 86066ns
> Starting task 81845273-41cb-4086-8d26-b58acd094ec7
> Forked command at 9131
> sh -c 'sleep 1000'
> I0115 18:42:25.652997 9114 exec.cpp:517] Executor sending status update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.654008 1785 slave.cpp:2932] Handling status update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 from executor(1)@172.17.0.2:51606
> I0115 18:42:25.654592 1788 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.654656 1788 status_update_manager.cpp:497] Creating
> StatusUpdate stream for task 81845273-41cb-4086-8d26-b58acd094ec7 of
> framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.655225 1788 status_update_manager.cpp:824] Checkpointing
> UPDATE for status update TASK_RUNNING (UUID:
> 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.657148 1788 status_update_manager.cpp:374] Forwarding update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
> I0115 18:42:25.657443 1794 slave.cpp:3284] Forwarding the update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
> I0115 18:42:25.657649 1794 slave.cpp:3178] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.657691 1794 slave.cpp:3194] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for
> task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to executor(1)@172.17.0.2:51606
> I0115 18:42:25.657877 1781 master.cpp:4789] Status update TASK_RUNNING
> (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.657943 1781 master.cpp:4837] Forwarding status update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.658174 1781 master.cpp:6445] Updating the state of task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> I0115 18:42:25.658334 9124 exec.cpp:341] Executor received status update
> acknowledgement 53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.658447 1790 sched.cpp:927] Scheduler::statusUpdate took
> 153056ns
> I0115 18:42:25.658833 1792 master.cpp:3947] Processing ACKNOWLEDGE call
> 53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129 on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.658998 1796 slave.cpp:596] Slave terminating
> I0115 18:42:25.659343 1782 master.cpp:1172] Slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1) disconnected
> I0115 18:42:25.659446 1782 master.cpp:2633] Disconnecting slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.659584 1782 master.cpp:2652] Deactivating slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.659844 1795 hierarchical.cpp:546] Slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 deactivated
> I0115 18:42:25.662204 1762 containerizer.cpp:140] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> W0115 18:42:25.662964 1762 backend.cpp:48] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0115 18:42:25.667950 1793 slave.cpp:191] Slave started on
> 367)@172.17.0.2:49129
> I0115 18:42:25.667984 1793 slave.cpp:192] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --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"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --oversubscribed_resources_interval="15secs"
> --perf_duration="10secs" --perf_interval="1mins"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj"
> I0115 18:42:25.668759 1793 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential'
> I0115 18:42:25.669105 1793 slave.cpp:322] Slave using credential for:
> test-principal
> I0115 18:42:25.669376 1793 resources.cpp:482] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0115 18:42:25.670003 1793 slave.cpp:392] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0115 18:42:25.670074 1793 slave.cpp:400] Slave attributes: [ ]
> I0115 18:42:25.670085 1793 slave.cpp:405] Slave hostname: e648fe109cb1
> I0115 18:42:25.671247 1795 state.cpp:58] Recovering state from
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta'
> I0115 18:42:25.671295 1795 state.cpp:698] No checkpointed resources found at
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/resources/resources.info'
> I0115 18:42:25.675850 1785 fetcher.cpp:81] Clearing fetcher cache
> I0115 18:42:25.675925 1785 slave.cpp:4512] Recovering framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.676005 1785 slave.cpp:5317] Recovering executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.677289 1795 status_update_manager.cpp:200] Recovering status
> update manager
> I0115 18:42:25.677331 1795 status_update_manager.cpp:208] Recovering
> executor '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.677425 1795 status_update_manager.cpp:497] Creating
> StatusUpdate stream for task 81845273-41cb-4086-8d26-b58acd094ec7 of
> framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.677716 1785 slave.cpp:677] Successfully attached file
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> I0115 18:42:25.678043 1795 status_update_manager.cpp:800] Replaying status
> update stream for task 81845273-41cb-4086-8d26-b58acd094ec7
> I0115 18:42:25.679199 1781 containerizer.cpp:386] Recovering containerizer
> I0115 18:42:25.679307 1781 containerizer.cpp:441] Recovering container
> 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' for executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.682132 1785 provisioner.cpp:245] Provisioner recovery complete
> I0115 18:42:25.683300 1783 slave.cpp:4364] Sending reconnect request to
> executor '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
> I0115 18:42:25.684046 9128 exec.cpp:254] Received reconnect request from
> slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.684902 1796 slave.cpp:2722] Re-registering executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.685632 9129 exec.cpp:231] Executor re-registered on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.687872 9129 exec.cpp:243] Executor::reregistered took 130269ns
> Re-registered executor on e648fe109cb1
> I0115 18:42:25.690438 1789 slave.cpp:2872] Cleaning up un-reregistered
> executors
> I0115 18:42:25.690439 1794 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:25.690556 1794 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:25.690580 1789 slave.cpp:4424] Finished recovery
> I0115 18:42:25.690608 1794 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 247279ns
> I0115 18:42:25.691195 1789 slave.cpp:4596] Querying resource estimator for
> oversubscribable resources
> I0115 18:42:25.691489 1791 status_update_manager.cpp:174] Pausing sending
> status updates
> I0115 18:42:25.691495 1789 slave.cpp:724] New master detected at
> [email protected]:49129
> I0115 18:42:25.691562 1789 slave.cpp:787] Authenticating with master
> [email protected]:49129
> I0115 18:42:25.691596 1789 slave.cpp:792] Using default CRAM-MD5
> authenticatee
> I0115 18:42:25.691777 1789 slave.cpp:760] Detecting new master
> I0115 18:42:25.691809 1792 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 18:42:25.691990 1789 slave.cpp:4610] Received oversubscribable
> resources from the resource estimator
> I0115 18:42:25.692188 1781 master.cpp:5521] Authenticating
> slave(367)@172.17.0.2:49129
> I0115 18:42:25.692342 1792 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(794)@172.17.0.2:49129
> I0115 18:42:25.692651 1793 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 18:42:25.692940 1787 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 18:42:25.693004 1787 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 18:42:25.693135 1794 authenticator.cpp:203] Received SASL
> authentication start
> I0115 18:42:25.693204 1794 authenticator.cpp:325] Authentication requires
> more steps
> I0115 18:42:25.693315 1787 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 18:42:25.693478 1783 authenticator.cpp:231] Received SASL
> authentication step
> I0115 18:42:25.693523 1783 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 18:42:25.693545 1783 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 18:42:25.693598 1783 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 18:42:25.693626 1783 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 18:42:25.693639 1783 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 18:42:25.693648 1783 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 18:42:25.693666 1783 authenticator.cpp:317] Authentication success
> I0115 18:42:25.693774 1787 authenticatee.cpp:298] Authentication success
> I0115 18:42:25.693836 1796 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(367)@172.17.0.2:49129
> I0115 18:42:25.693902 1790 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(794)@172.17.0.2:49129
> I0115 18:42:25.694314 1784 slave.cpp:855] Successfully authenticated with
> master [email protected]:49129
> I0115 18:42:25.694669 1784 slave.cpp:1249] Will retry registration in
> 15390ns if necessary
> I0115 18:42:25.695060 1794 master.cpp:4395] Re-registering slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.695238 1791 slave.cpp:1249] Will retry registration in
> 22.225404ms if necessary
> I0115 18:42:25.695515 1794 master.cpp:4582] Sending updated checkpointed
> resources to slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at
> slave(367)@172.17.0.2:49129 (e648fe109cb1)
> I0115 18:42:25.695637 1791 slave.cpp:999] Re-registered with master
> [email protected]:49129
> I0115 18:42:25.695763 1788 hierarchical.cpp:534] Slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 reactivated
> I0115 18:42:25.695778 1784 status_update_manager.cpp:181] Resuming sending
> status updates
> I0115 18:42:25.695786 1791 slave.cpp:1035] Forwarding total oversubscribed
> resources
> W0115 18:42:25.695839 1784 status_update_manager.cpp:188] Resending status
> update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.695883 1784 status_update_manager.cpp:374] Forwarding update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
> I0115 18:42:25.696197 1794 master.cpp:4395] Re-registering slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.696455 1791 slave.cpp:2272] Updated checkpointed resources
> from to
> I0115 18:42:25.696579 1794 master.cpp:4582] Sending updated checkpointed
> resources to slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at
> slave(367)@172.17.0.2:49129 (e648fe109cb1)
> I0115 18:42:25.696653 1791 slave.cpp:3284] Forwarding the update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
> I0115 18:42:25.696790 1794 master.cpp:4644] Received update of slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
> (e648fe109cb1) with total oversubscribed resources
> I0115 18:42:25.696996 1791 slave.cpp:2176] Updating framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 pid to @0.0.0.0:0
> I0115 18:42:25.697074 1791 slave.cpp:2192] Checkpointing framework pid
> '@0.0.0.0:0' to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.pid'
> I0115 18:42:25.697226 1794 master.cpp:4789] Status update TASK_RUNNING
> (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.697279 1794 master.cpp:4837] Forwarding status update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.697571 1794 master.cpp:6445] Updating the state of task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> W0115 18:42:25.697615 1791 slave.cpp:1016] Already re-registered with master
> [email protected]:49129
> I0115 18:42:25.697641 1791 slave.cpp:1035] Forwarding total oversubscribed
> resources
> I0115 18:42:25.697654 1787 status_update_manager.cpp:181] Resuming sending
> status updates
> W0115 18:42:25.697703 1787 status_update_manager.cpp:188] Resending status
> update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.697736 1788 sched.cpp:927] Scheduler::statusUpdate took
> 36082ns
> I0115 18:42:25.697758 1787 status_update_manager.cpp:374] Forwarding update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
> I0115 18:42:25.697836 1791 slave.cpp:2176] Updating framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 pid to
> [email protected]:49129
> I0115 18:42:25.697890 1791 slave.cpp:2192] Checkpointing framework pid
> '[email protected]:49129' to
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.pid'
> I0115 18:42:25.697940 1786 hierarchical.cpp:517] Slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0115 18:42:25.698093 1796 master.cpp:4644] Received update of slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
> (e648fe109cb1) with total oversubscribed resources
> I0115 18:42:25.698228 1786 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:25.698300 1786 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:25.698341 1786 hierarchical.cpp:1097] Performed allocation for
> slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 339284ns
> I0115 18:42:25.698362 1794 status_update_manager.cpp:181] Resuming sending
> status updates
> I0115 18:42:25.698397 1796 master.cpp:3947] Processing ACKNOWLEDGE call
> 53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129 on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> W0115 18:42:25.698410 1794 status_update_manager.cpp:188] Resending status
> update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.698447 1794 status_update_manager.cpp:374] Forwarding update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
> I0115 18:42:25.698626 1791 slave.cpp:2272] Updated checkpointed resources
> from to
> I0115 18:42:25.698807 1791 slave.cpp:3352] Sending message for framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to
> [email protected]:49129
> I0115 18:42:25.699002 1791 slave.cpp:3284] Forwarding the update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
> I0115 18:42:25.699121 1783 sched.cpp:1063] Scheduler::frameworkMessage took
> 89916ns
> I0115 18:42:25.699154 1786 hierarchical.cpp:517] Slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0115 18:42:25.699357 1786 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:25.699419 1786 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:25.699421 1782 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.699398 1784 master.cpp:4789] Status update TASK_RUNNING
> (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.699455 1786 hierarchical.cpp:1097] Performed allocation for
> slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 230854ns
> I0115 18:42:25.699476 1784 master.cpp:4837] Forwarding status update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.699515 1791 slave.cpp:3284] Forwarding the update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
> I0115 18:42:25.699589 1782 status_update_manager.cpp:824] Checkpointing ACK
> for status update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9)
> for task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.699712 1784 master.cpp:6445] Updating the state of task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> I0115 18:42:25.699880 1783 sched.cpp:927] Scheduler::statusUpdate took
> 24047ns
> I0115 18:42:25.699972 1784 master.cpp:4789] Status update TASK_RUNNING
> (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:25.700028 1784 master.cpp:4837] Forwarding status update
> TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.700233 1784 master.cpp:6445] Updating the state of task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> I0115 18:42:25.700458 1793 sched.cpp:927] Scheduler::statusUpdate took
> 16402ns
> I0115 18:42:25.700492 1784 master.cpp:3947] Processing ACKNOWLEDGE call
> 53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129 on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.700654 1791 slave.cpp:2343] Status update manager
> successfully handled status update acknowledgement (UUID:
> 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.700763 1784 master.cpp:3947] Processing ACKNOWLEDGE call
> 53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129 on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:25.700933 1781 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> E0115 18:42:25.701177 1787 slave.cpp:2336] Failed to handle status update
> acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000: Unexpected status update
> acknowledgment (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:25.701195 1781 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> E0115 18:42:25.701463 1785 slave.cpp:2336] Failed to handle status update
> acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000: Unexpected status update
> acknowledgment (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> 2016-01-15
> 18:42:25,786:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0115 18:42:26.691529 1792 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:26.691583 1792 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:26.691611 1792 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 265866ns
> I0115 18:42:27.692991 1781 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:27.693042 1781 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:27.693068 1781 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 221232ns
> I0115 18:42:28.693617 1792 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:28.693681 1792 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:28.693709 1792 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 299122ns
> 2016-01-15
> 18:42:29,122:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0115 18:42:29.694614 1786 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:29.694679 1786 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:29.694710 1786 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 325965ns
> I0115 18:42:30.695550 1796 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:30.695654 1796 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:30.695700 1796 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 501134ns
> I0115 18:42:31.696338 1783 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:31.696422 1783 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:31.696457 1783 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 420467ns
> 2016-01-15
> 18:42:32,459:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0115 18:42:32.697325 1784 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:32.697397 1784 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:32.697429 1784 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 384033ns
> I0115 18:42:33.698457 1788 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:33.698524 1788 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:33.698556 1788 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 338490ns
> I0115 18:42:34.699501 1794 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:34.699554 1794 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:34.699581 1794 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 261802ns
> I0115 18:42:35.700134 1785 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:35.700199 1785 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:35.700234 1785 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 306905ns
> 2016-01-15
> 18:42:35,795:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0115 18:42:36.700793 1796 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:36.700873 1796 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:36.700930 1796 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 282620ns
> I0115 18:42:37.701592 1789 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:37.701655 1789 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:37.701690 1789 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 250604ns
> I0115 18:42:38.702301 1792 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:38.702378 1792 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:38.702410 1792 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 374668ns
> 2016-01-15
> 18:42:39,132:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0115 18:42:39.703342 1783 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:39.703418 1783 hierarchical.cpp:1419] No inverse offers to send
> out!
> I0115 18:42:39.703454 1783 hierarchical.cpp:1075] Performed allocation for 1
> slaves in 342247ns
> I0115 18:42:40.692309 1794 slave.cpp:4596] Querying resource estimator for
> oversubscribable resources
> I0115 18:42:40.692667 1794 slave.cpp:4610] Received oversubscribable
> resources from the resource estimator
> ../../src/tests/slave_tests.cpp:2996: Failure
> Failed to wait 15secs for executorToFrameworkMessage1
> I0115 18:42:40.698703 1787 master.cpp:1211] Framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129 disconnected
> I0115 18:42:40.698753 1787 master.cpp:2574] Disconnecting framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129
> I0115 18:42:40.698802 1787 master.cpp:2598] Deactivating framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129
> I0115 18:42:40.699072 1787 master.cpp:1235] Giving framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129 0ns to
> failover
> I0115 18:42:40.699309 1789 hierarchical.cpp:365] Deactivated framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:40.699407 1790 master.cpp:5202] Framework failover timeout,
> removing framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129
> I0115 18:42:40.699455 1790 master.cpp:5933] Removing framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> [email protected]:49129
> I0115 18:42:40.699699 1786 slave.cpp:2007] Asked to shut down framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 by [email protected]:49129
> I0115 18:42:40.699720 1790 master.cpp:6445] Updating the state of task
> 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_KILLED, status
> update state: TASK_KILLED)
> I0115 18:42:40.699760 1786 slave.cpp:2032] Shutting down framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:40.699887 1786 slave.cpp:4057] Shutting down executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
> I0115 18:42:40.700575 1781 hierarchical.cpp:876] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 from framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:40.700724 1790 master.cpp:6511] Removing task
> 81845273-41cb-4086-8d26-b58acd094ec7 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 on slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
> (e648fe109cb1)
> I0115 18:42:40.701076 9121 exec.cpp:381] Executor asked to shutdown
> I0115 18:42:40.701274 9123 exec.cpp:80] Scheduling shutdown of the executor
> I0115 18:42:40.701431 9121 exec.cpp:396] Executor::shutdown took 164650ns
> Shutting down
> Sending SIGTERM to process tree at pid 9131
> I0115 18:42:40.703037 1790 master.cpp:1025] Master terminating
> I0115 18:42:40.703275 1788 hierarchical.cpp:320] Removed framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:40.703676 1787 slave.cpp:3412] [email protected]:49129 exited
> W0115 18:42:40.703718 1787 slave.cpp:3415] Master disconnected! Waiting for
> a new master to be elected
> I0115 18:42:40.703891 1788 hierarchical.cpp:492] Removed slave
> 544823be-76b5-47be-b326-2cd6d6a700b8-S0
> I0115 18:42:40.704502 1796 hierarchical.cpp:1325] No resources available to
> allocate!
> I0115 18:42:40.704558 1796 hierarchical.cpp:1075] Performed allocation for 0
> slaves in 128159ns
> Killing the following process trees:
> [
> --- 9131 sleep 1000
> ]
> I0115 18:42:40.708323 1791 containerizer.cpp:1204] Destroying container
> 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> I0115 18:42:40.717231 1794 slave.cpp:3412] executor(1)@172.17.0.2:51606
> exited
> I0115 18:42:40.776173 1788 containerizer.cpp:1420] Executor for container
> 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' has exited
> I0115 18:42:40.776197 1783 containerizer.cpp:1420] Executor for container
> 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' has exited
> I0115 18:42:40.776271 1788 containerizer.cpp:1204] Destroying container
> 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> I0115 18:42:40.777791 1785 provisioner.cpp:306] Ignoring destroy request for
> unknown container dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8
> I0115 18:42:40.778194 1790 slave.cpp:3745] Executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 terminated with signal Killed
> I0115 18:42:40.778254 1790 slave.cpp:3849] Cleaning up executor
> '81845273-41cb-4086-8d26-b58acd094ec7' of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
> I0115 18:42:40.778851 1787 gc.cpp:54] Scheduling
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> for gc 6.99999098854222days in the future
> I0115 18:42:40.779085 1787 gc.cpp:54] Scheduling
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7'
> for gc 6.99999098597333days in the future
> I0115 18:42:40.779307 1790 slave.cpp:3937] Cleaning up framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:40.779306 1787 gc.cpp:54] Scheduling
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
> for gc 6.99999098406222days in the future
> I0115 18:42:40.779448 1794 status_update_manager.cpp:282] Closing status
> update streams for framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:40.779481 1787 gc.cpp:54] Scheduling
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7'
> for gc 6.99999098131852days in the future
> I0115 18:42:40.779713 1794 status_update_manager.cpp:528] Cleaning up status
> update stream for task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000
> I0115 18:42:40.779798 1787 gc.cpp:54] Scheduling
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000'
> for gc 6.99999097825185days in the future
> I0115 18:42:40.779907 1783 slave.cpp:596] Slave terminating
> I0115 18:42:40.779973 1787 gc.cpp:54] Scheduling
> '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000'
> for gc 6.99999097689778days in the future
> I0115 18:42:40.781146 1791 provisioner.cpp:306] Ignoring destroy request for
> unknown container dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8
> ../../3rdparty/libprocess/include/process/gmock.hpp:363: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock,
> filter(testing::A<const MessageEvent&>()))...
> Expected args: message matcher (8-byte object <58-EC 02-44 74-7F 00-00>,
> 1, 1)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> ../../3rdparty/libprocess/include/process/gmock.hpp:363: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock,
> filter(testing::A<const MessageEvent&>()))...
> Expected args: message matcher (8-byte object <58-EC 02-44 74-7F 00-00>,
> 1, 1-byte object <D8>)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] SlaveTest.HTTPSchedulerSlaveRestart (15394 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
