mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Joseph Wu (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (MESOS-4676) ROOT_DOCKER_Logs is flaky.
Date Thu, 25 Feb 2016 20:40:18 GMT

    [ https://issues.apache.org/jira/browse/MESOS-4676?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15167831#comment-15167831
] 

Joseph Wu commented on MESOS-4676:
----------------------------------

{code}
commit d0d4d5a64e8aa17f0bc364060d98690b49037550
Author: Joseph Wu <joseph@mesosphere.io>
Date:   Thu Feb 25 12:22:07 2016 +0100

    Fixed flakiness in DockerContainerizerTest.ROOT_DOCKER_Logs.
    
    Adds the `unbuffer` utility in front of each `echo` in the test.
    Since Docker appears to handle simultaneous stdout/stderr in a
    non-robust fashion, this mitigates the amount of overlap the two
    streams will have in the test.
    
    Review: https://reviews.apache.org/r/43963/
{code}

> ROOT_DOCKER_Logs is flaky.
> --------------------------
>
>                 Key: MESOS-4676
>                 URL: https://issues.apache.org/jira/browse/MESOS-4676
>             Project: Mesos
>          Issue Type: Bug
>    Affects Versions: 0.27
>         Environment: CentOS 7 with SSL.
>            Reporter: Bernd Mathiske
>            Assignee: Joseph Wu
>              Labels: flaky, mesosphere, test
>             Fix For: 0.28.0
>
>
> {noformat}
> [18:06:25][Step 8/8] [ RUN      ] DockerContainerizerTest.ROOT_DOCKER_Logs
> [18:06:25][Step 8/8] I0215 17:06:25.256103  1740 leveldb.cpp:174] Opened db in 6.548327ms
> [18:06:25][Step 8/8] I0215 17:06:25.258002  1740 leveldb.cpp:181] Compacted db in 1.837816ms
> [18:06:25][Step 8/8] I0215 17:06:25.258059  1740 leveldb.cpp:196] Created db iterator
in 22044ns
> [18:06:25][Step 8/8] I0215 17:06:25.258076  1740 leveldb.cpp:202] Seeked to beginning
of db in 2347ns
> [18:06:25][Step 8/8] I0215 17:06:25.258091  1740 leveldb.cpp:271] Iterated through 0
keys in the db in 571ns
> [18:06:25][Step 8/8] I0215 17:06:25.258152  1740 replica.cpp:779] Replica recovered with
log positions 0 -> 0 with 1 holes and 0 unlearned
> [18:06:25][Step 8/8] I0215 17:06:25.258936  1758 recover.cpp:447] Starting replica recovery
> [18:06:25][Step 8/8] I0215 17:06:25.259177  1758 recover.cpp:473] Replica is in EMPTY
status
> [18:06:25][Step 8/8] I0215 17:06:25.260327  1757 replica.cpp:673] Replica in EMPTY status
received a broadcasted recover request from (13608)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.260545  1758 recover.cpp:193] Received a recover
response from a replica in EMPTY status
> [18:06:25][Step 8/8] I0215 17:06:25.261065  1757 master.cpp:376] Master 112363e2-c680-4946-8fee-d0626ed8b21e
(ip-172-30-2-239.mesosphere.io) started on 172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.261209  1761 recover.cpp:564] Updating replica status
to STARTING
> [18:06:25][Step 8/8] I0215 17:06:25.261086  1757 master.cpp:378] Flags at startup: --acls=""
--allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true"
--authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/HncLLj/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="100secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs"
--slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/tmp/HncLLj/master" --zk_session_timeout="10secs"
> [18:06:25][Step 8/8] I0215 17:06:25.261446  1757 master.cpp:423] Master only allowing
authenticated frameworks to register
> [18:06:25][Step 8/8] I0215 17:06:25.261456  1757 master.cpp:428] Master only allowing
authenticated slaves to register
> [18:06:25][Step 8/8] I0215 17:06:25.261462  1757 credentials.hpp:35] Loading credentials
for authentication from '/tmp/HncLLj/credentials'
> [18:06:25][Step 8/8] I0215 17:06:25.261723  1757 master.cpp:468] Using default 'crammd5'
authenticator
> [18:06:25][Step 8/8] I0215 17:06:25.261855  1757 master.cpp:537] Using default 'basic'
HTTP authenticator
> [18:06:25][Step 8/8] I0215 17:06:25.262022  1757 master.cpp:571] Authorization enabled
> [18:06:25][Step 8/8] I0215 17:06:25.262177  1755 hierarchical.cpp:144] Initialized hierarchical
allocator process
> [18:06:25][Step 8/8] I0215 17:06:25.262177  1758 whitelist_watcher.cpp:77] No whitelist
given
> [18:06:25][Step 8/8] I0215 17:06:25.262899  1760 leveldb.cpp:304] Persisting metadata
(8 bytes) to leveldb took 1.517992ms
> [18:06:25][Step 8/8] I0215 17:06:25.262924  1760 replica.cpp:320] Persisted replica status
to STARTING
> [18:06:25][Step 8/8] I0215 17:06:25.263144  1754 recover.cpp:473] Replica is in STARTING
status
> [18:06:25][Step 8/8] I0215 17:06:25.264010  1757 master.cpp:1712] The newly elected leader
is master@172.30.2.239:39785 with id 112363e2-c680-4946-8fee-d0626ed8b21e
> [18:06:25][Step 8/8] I0215 17:06:25.264044  1757 master.cpp:1725] Elected as the leading
master!
> [18:06:25][Step 8/8] I0215 17:06:25.264061  1757 master.cpp:1470] Recovering from registrar
> [18:06:25][Step 8/8] I0215 17:06:25.264117  1760 replica.cpp:673] Replica in STARTING
status received a broadcasted recover request from (13610)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.264197  1758 registrar.cpp:307] Recovering registrar
> [18:06:25][Step 8/8] I0215 17:06:25.264827  1756 recover.cpp:193] Received a recover
response from a replica in STARTING status
> [18:06:25][Step 8/8] I0215 17:06:25.265219  1757 recover.cpp:564] Updating replica status
to VOTING
> [18:06:25][Step 8/8] I0215 17:06:25.267302  1754 leveldb.cpp:304] Persisting metadata
(8 bytes) to leveldb took 1.887739ms
> [18:06:25][Step 8/8] I0215 17:06:25.267326  1754 replica.cpp:320] Persisted replica status
to VOTING
> [18:06:25][Step 8/8] I0215 17:06:25.267453  1759 recover.cpp:578] Successfully joined
the Paxos group
> [18:06:25][Step 8/8] I0215 17:06:25.267632  1759 recover.cpp:462] Recover process terminated
> [18:06:25][Step 8/8] I0215 17:06:25.268007  1757 log.cpp:659] Attempting to start the
writer
> [18:06:25][Step 8/8] I0215 17:06:25.269055  1759 replica.cpp:493] Replica received implicit
promise request from (13611)@172.30.2.239:39785 with proposal 1
> [18:06:25][Step 8/8] I0215 17:06:25.270488  1759 leveldb.cpp:304] Persisting metadata
(8 bytes) to leveldb took 1.406068ms
> [18:06:25][Step 8/8] I0215 17:06:25.270511  1759 replica.cpp:342] Persisted promised
to 1
> [18:06:25][Step 8/8] I0215 17:06:25.271078  1761 coordinator.cpp:238] Coordinator attempting
to fill missing positions
> [18:06:25][Step 8/8] I0215 17:06:25.272146  1756 replica.cpp:388] Replica received explicit
promise request from (13612)@172.30.2.239:39785 for position 0 with proposal 2
> [18:06:25][Step 8/8] I0215 17:06:25.273478  1756 leveldb.cpp:341] Persisting action (8
bytes) to leveldb took 1.297217ms
> [18:06:25][Step 8/8] I0215 17:06:25.273500  1756 replica.cpp:712] Persisted action at
0
> [18:06:25][Step 8/8] I0215 17:06:25.274355  1757 replica.cpp:537] Replica received write
request for position 0 from (13613)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.274405  1757 leveldb.cpp:436] Reading position from
leveldb took 25294ns
> [18:06:25][Step 8/8] I0215 17:06:25.275800  1757 leveldb.cpp:341] Persisting action (14
bytes) to leveldb took 1.362978ms
> [18:06:25][Step 8/8] I0215 17:06:25.275823  1757 replica.cpp:712] Persisted action at
0
> [18:06:25][Step 8/8] I0215 17:06:25.276348  1755 replica.cpp:691] Replica received learned
notice for position 0 from @0.0.0.0:0
> [18:06:25][Step 8/8] I0215 17:06:25.277765  1755 leveldb.cpp:341] Persisting action (16
bytes) to leveldb took 1.391531ms
> [18:06:25][Step 8/8] I0215 17:06:25.277788  1755 replica.cpp:712] Persisted action at
0
> [18:06:25][Step 8/8] I0215 17:06:25.277802  1755 replica.cpp:697] Replica learned NOP
action at position 0
> [18:06:25][Step 8/8] I0215 17:06:25.278336  1754 log.cpp:675] Writer started with ending
position 0
> [18:06:25][Step 8/8] I0215 17:06:25.279371  1755 leveldb.cpp:436] Reading position from
leveldb took 29214ns
> [18:06:25][Step 8/8] I0215 17:06:25.280272  1758 registrar.cpp:340] Successfully fetched
the registry (0B) in 16.02688ms
> [18:06:25][Step 8/8] I0215 17:06:25.280385  1758 registrar.cpp:439] Applied 1 operations
in 31040ns; attempting to update the 'registry'
> [18:06:25][Step 8/8] I0215 17:06:25.281054  1755 log.cpp:683] Attempting to append 210
bytes to the log
> [18:06:25][Step 8/8] I0215 17:06:25.281165  1757 coordinator.cpp:348] Coordinator attempting
to write APPEND action at position 1
> [18:06:25][Step 8/8] I0215 17:06:25.281780  1757 replica.cpp:537] Replica received write
request for position 1 from (13614)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.283159  1757 leveldb.cpp:341] Persisting action (229
bytes) to leveldb took 1.348041ms
> [18:06:25][Step 8/8] I0215 17:06:25.283184  1757 replica.cpp:712] Persisted action at
1
> [18:06:25][Step 8/8] I0215 17:06:25.283695  1759 replica.cpp:691] Replica received learned
notice for position 1 from @0.0.0.0:0
> [18:06:25][Step 8/8] I0215 17:06:25.285059  1759 leveldb.cpp:341] Persisting action (231
bytes) to leveldb took 1.334577ms
> [18:06:25][Step 8/8] I0215 17:06:25.285084  1759 replica.cpp:712] Persisted action at
1
> [18:06:25][Step 8/8] I0215 17:06:25.285099  1759 replica.cpp:697] Replica learned APPEND
action at position 1
> [18:06:25][Step 8/8] I0215 17:06:25.285910  1758 registrar.cpp:484] Successfully updated
the 'registry' in 5.46816ms
> [18:06:25][Step 8/8] I0215 17:06:25.286043  1758 registrar.cpp:370] Successfully recovered
registrar
> [18:06:25][Step 8/8] I0215 17:06:25.286121  1755 log.cpp:702] Attempting to truncate
the log to 1
> [18:06:25][Step 8/8] I0215 17:06:25.286301  1756 coordinator.cpp:348] Coordinator attempting
to write TRUNCATE action at position 2
> [18:06:25][Step 8/8] I0215 17:06:25.286478  1759 hierarchical.cpp:171] Skipping recovery
of hierarchical allocator: nothing to recover
> [18:06:25][Step 8/8] I0215 17:06:25.286476  1754 master.cpp:1522] Recovered 0 slaves
from the Registry (171B) ; allowing 10mins for slaves to re-register
> [18:06:25][Step 8/8] I0215 17:06:25.287137  1755 replica.cpp:537] Replica received write
request for position 2 from (13615)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.289104  1755 leveldb.cpp:341] Persisting action (16
bytes) to leveldb took 1.938609ms
> [18:06:25][Step 8/8] I0215 17:06:25.289127  1755 replica.cpp:712] Persisted action at
2
> [18:06:25][Step 8/8] I0215 17:06:25.289667  1759 replica.cpp:691] Replica received learned
notice for position 2 from @0.0.0.0:0
> [18:06:25][Step 8/8] I0215 17:06:25.290956  1759 leveldb.cpp:341] Persisting action (18
bytes) to leveldb took 1.256421ms
> [18:06:25][Step 8/8] I0215 17:06:25.291007  1759 leveldb.cpp:399] Deleting ~1 keys from
leveldb took 28064ns
> [18:06:25][Step 8/8] I0215 17:06:25.291021  1759 replica.cpp:712] Persisted action at
2
> [18:06:25][Step 8/8] I0215 17:06:25.291038  1759 replica.cpp:697] Replica learned TRUNCATE
action at position 2
> [18:06:25][Step 8/8] I0215 17:06:25.300550  1760 slave.cpp:193] Slave started on 393)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.300573  1760 slave.cpp:194] 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/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/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/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/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="/mnt/teamcity/work/4240ba9ddd0997c3/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/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N"
> [18:06:25][Step 8/8] I0215 17:06:25.300868  1760 credentials.hpp:83] Loading credential
for authentication from '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/credential'
> [18:06:25][Step 8/8] I0215 17:06:25.301030  1760 slave.cpp:324] Slave using credential
for: test-principal
> [18:06:25][Step 8/8] I0215 17:06:25.301180  1760 resources.cpp:576] Parsing resources
as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> [18:06:25][Step 8/8] Trying semicolon-delimited string format instead
> [18:06:25][Step 8/8] I0215 17:06:25.301553  1760 slave.cpp:464] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [18:06:25][Step 8/8] I0215 17:06:25.301609  1760 slave.cpp:472] Slave attributes: [ 
]
> [18:06:25][Step 8/8] I0215 17:06:25.301620  1760 slave.cpp:477] Slave hostname: ip-172-30-2-239.mesosphere.io
> [18:06:25][Step 8/8] I0215 17:06:25.302417  1757 state.cpp:58] Recovering state from
'/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/meta'
> [18:06:25][Step 8/8] I0215 17:06:25.302515  1740 sched.cpp:222] Version: 0.28.0
> [18:06:25][Step 8/8] I0215 17:06:25.302772  1755 status_update_manager.cpp:200] Recovering
status update manager
> [18:06:25][Step 8/8] I0215 17:06:25.302956  1758 docker.cpp:559] Recovering Docker containers
> [18:06:25][Step 8/8] I0215 17:06:25.303050  1761 sched.cpp:326] New master detected at
master@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.303133  1754 slave.cpp:4565] Finished recovery
> [18:06:25][Step 8/8] I0215 17:06:25.303154  1761 sched.cpp:382] Authenticating with master
master@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.303169  1761 sched.cpp:389] Using default CRAM-MD5
authenticatee
> [18:06:25][Step 8/8] I0215 17:06:25.303364  1759 authenticatee.cpp:121] Creating new
client SASL connection
> [18:06:25][Step 8/8] I0215 17:06:25.303467  1754 slave.cpp:4737] Querying resource estimator
for oversubscribable resources
> [18:06:25][Step 8/8] I0215 17:06:25.303668  1756 master.cpp:5523] Authenticating scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.303707  1760 status_update_manager.cpp:174] Pausing
sending status updates
> [18:06:25][Step 8/8] I0215 17:06:25.303707  1754 slave.cpp:796] New master detected at
master@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.303767  1755 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(829)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.303791  1754 slave.cpp:859] Authenticating with master
master@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.303805  1754 slave.cpp:864] Using default CRAM-MD5
authenticatee
> [18:06:25][Step 8/8] I0215 17:06:25.303956  1754 slave.cpp:832] Detecting new master
> [18:06:25][Step 8/8] I0215 17:06:25.303971  1761 authenticatee.cpp:121] Creating new
client SASL connection
> [18:06:25][Step 8/8] I0215 17:06:25.303984  1760 authenticator.cpp:98] Creating new server
SASL connection
> [18:06:25][Step 8/8] I0215 17:06:25.304131  1754 slave.cpp:4751] Received oversubscribable
resources  from the resource estimator
> [18:06:25][Step 8/8] I0215 17:06:25.304275  1757 master.cpp:5523] Authenticating slave(393)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.304344  1754 authenticatee.cpp:212] Received SASL
authentication mechanisms: CRAM-MD5
> [18:06:25][Step 8/8] I0215 17:06:25.304369  1754 authenticatee.cpp:238] Attempting to
authenticate with mechanism 'CRAM-MD5'
> [18:06:25][Step 8/8] I0215 17:06:25.304373  1761 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(830)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.304440  1757 authenticator.cpp:203] Received SASL
authentication start
> [18:06:25][Step 8/8] I0215 17:06:25.304491  1757 authenticator.cpp:325] Authentication
requires more steps
> [18:06:25][Step 8/8] I0215 17:06:25.304548  1754 authenticator.cpp:98] Creating new server
SASL connection
> [18:06:25][Step 8/8] I0215 17:06:25.304582  1761 authenticatee.cpp:258] Received SASL
authentication step
> [18:06:25][Step 8/8] I0215 17:06:25.304688  1761 authenticator.cpp:231] Received SASL
authentication step
> [18:06:25][Step 8/8] I0215 17:06:25.304714  1761 auxprop.cpp:107] Request to lookup properties
for user: 'test-principal' realm: 'ip-172-30-2-239.mesosphere.io' server FQDN: 'ip-172-30-2-239.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
false 
> [18:06:25][Step 8/8] I0215 17:06:25.304723  1761 auxprop.cpp:179] Looking up auxiliary
property '*userPassword'
> [18:06:25][Step 8/8] I0215 17:06:25.304767  1761 auxprop.cpp:179] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
> [18:06:25][Step 8/8] I0215 17:06:25.304805  1761 auxprop.cpp:107] Request to lookup properties
for user: 'test-principal' realm: 'ip-172-30-2-239.mesosphere.io' server FQDN: 'ip-172-30-2-239.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
true 
> [18:06:25][Step 8/8] I0215 17:06:25.304817  1761 auxprop.cpp:129] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [18:06:25][Step 8/8] I0215 17:06:25.304824  1761 auxprop.cpp:129] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> [18:06:25][Step 8/8] I0215 17:06:25.304836  1761 authenticator.cpp:317] Authentication
success
> [18:06:25][Step 8/8] I0215 17:06:25.304841  1758 authenticatee.cpp:212] Received SASL
authentication mechanisms: CRAM-MD5
> [18:06:25][Step 8/8] I0215 17:06:25.304870  1758 authenticatee.cpp:238] Attempting to
authenticate with mechanism 'CRAM-MD5'
> [18:06:25][Step 8/8] I0215 17:06:25.304909  1757 authenticatee.cpp:298] Authentication
success
> [18:06:25][Step 8/8] I0215 17:06:25.304983  1756 authenticator.cpp:203] Received SASL
authentication start
> [18:06:25][Step 8/8] I0215 17:06:25.305033  1756 authenticator.cpp:325] Authentication
requires more steps
> [18:06:25][Step 8/8] I0215 17:06:25.305042  1759 master.cpp:5553] Successfully authenticated
principal 'test-principal' at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305071  1755 authenticator.cpp:431] Authentication
session cleanup for crammd5_authenticatee(829)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305124  1756 authenticatee.cpp:258] Received SASL
authentication step
> [18:06:25][Step 8/8] I0215 17:06:25.305222  1758 sched.cpp:471] Successfully authenticated
with master master@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305246  1758 sched.cpp:776] Sending SUBSCRIBE call
to master@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305286  1760 authenticator.cpp:231] Received SASL
authentication step
> [18:06:25][Step 8/8] I0215 17:06:25.305310  1760 auxprop.cpp:107] Request to lookup properties
for user: 'test-principal' realm: 'ip-172-30-2-239.mesosphere.io' server FQDN: 'ip-172-30-2-239.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
false 
> [18:06:25][Step 8/8] I0215 17:06:25.305318  1760 auxprop.cpp:179] Looking up auxiliary
property '*userPassword'
> [18:06:25][Step 8/8] I0215 17:06:25.305344  1760 auxprop.cpp:179] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
> [18:06:25][Step 8/8] I0215 17:06:25.305363  1758 sched.cpp:809] Will retry registration
in 1.888777185secs if necessary
> [18:06:25][Step 8/8] I0215 17:06:25.305379  1760 auxprop.cpp:107] Request to lookup properties
for user: 'test-principal' realm: 'ip-172-30-2-239.mesosphere.io' server FQDN: 'ip-172-30-2-239.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID:
true 
> [18:06:25][Step 8/8] I0215 17:06:25.305397  1760 auxprop.cpp:129] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [18:06:25][Step 8/8] I0215 17:06:25.305408  1760 auxprop.cpp:129] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> [18:06:25][Step 8/8] I0215 17:06:25.305426  1760 authenticator.cpp:317] Authentication
success
> [18:06:25][Step 8/8] I0215 17:06:25.305466  1761 master.cpp:2280] Received SUBSCRIBE
call for framework 'default' at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305506  1756 authenticatee.cpp:298] Authentication
success
> [18:06:25][Step 8/8] I0215 17:06:25.305534  1761 master.cpp:1751] Authorizing framework
principal 'test-principal' to receive offers for role '*'
> [18:06:25][Step 8/8] I0215 17:06:25.305625  1755 authenticator.cpp:431] Authentication
session cleanup for crammd5_authenticatee(830)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305701  1761 master.cpp:5553] Successfully authenticated
principal 'test-principal' at slave(393)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305831  1758 slave.cpp:927] Successfully authenticated
with master master@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.305902  1757 master.cpp:2351] Subscribing framework
default with checkpointing disabled and capabilities [  ]
> [18:06:25][Step 8/8] I0215 17:06:25.305953  1758 slave.cpp:1321] Will retry registration
in 1.941456ms if necessary
> [18:06:25][Step 8/8] I0215 17:06:25.306280  1761 hierarchical.cpp:265] Added framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:25][Step 8/8] I0215 17:06:25.306352  1759 sched.cpp:703] Framework registered
with 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:25][Step 8/8] I0215 17:06:25.306363  1761 hierarchical.cpp:1403] No resources
available to allocate!
> [18:06:25][Step 8/8] I0215 17:06:25.306401  1761 hierarchical.cpp:1498] No inverse offers
to send out!
> [18:06:25][Step 8/8] I0215 17:06:25.306432  1761 hierarchical.cpp:1096] Performed allocation
for 0 slaves in 126082ns
> [18:06:25][Step 8/8] I0215 17:06:25.306447  1759 sched.cpp:717] Scheduler::registered
took 67960ns
> [18:06:25][Step 8/8] I0215 17:06:25.306437  1757 master.cpp:4237] Registering slave at
slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io) with id 112363e2-c680-4946-8fee-d0626ed8b21e-S0
> [18:06:25][Step 8/8] I0215 17:06:25.306884  1759 registrar.cpp:439] Applied 1 operations
in 63175ns; attempting to update the 'registry'
> [18:06:25][Step 8/8] I0215 17:06:25.307592  1756 log.cpp:683] Attempting to append 396
bytes to the log
> [18:06:25][Step 8/8] I0215 17:06:25.307724  1760 coordinator.cpp:348] Coordinator attempting
to write APPEND action at position 3
> [18:06:25][Step 8/8] I0215 17:06:25.308398  1760 replica.cpp:537] Replica received write
request for position 3 from (13622)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.308473  1755 slave.cpp:1321] Will retry registration
in 37.671741ms if necessary
> [18:06:25][Step 8/8] I0215 17:06:25.308627  1758 master.cpp:4225] Ignoring register slave
message from slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io) as admission is
already in progress
> [18:06:25][Step 8/8] I0215 17:06:25.310000  1760 leveldb.cpp:341] Persisting action (415
bytes) to leveldb took 1.556814ms
> [18:06:25][Step 8/8] I0215 17:06:25.310025  1760 replica.cpp:712] Persisted action at
3
> [18:06:25][Step 8/8] I0215 17:06:25.310541  1755 replica.cpp:691] Replica received learned
notice for position 3 from @0.0.0.0:0
> [18:06:25][Step 8/8] I0215 17:06:25.311928  1755 leveldb.cpp:341] Persisting action (417
bytes) to leveldb took 1.357404ms
> [18:06:25][Step 8/8] I0215 17:06:25.311950  1755 replica.cpp:712] Persisted action at
3
> [18:06:25][Step 8/8] I0215 17:06:25.311966  1755 replica.cpp:697] Replica learned APPEND
action at position 3
> [18:06:25][Step 8/8] I0215 17:06:25.313117  1755 registrar.cpp:484] Successfully updated
the 'registry' in 6.16704ms
> [18:06:25][Step 8/8] I0215 17:06:25.313297  1758 log.cpp:702] Attempting to truncate
the log to 3
> [18:06:25][Step 8/8] I0215 17:06:25.313391  1755 coordinator.cpp:348] Coordinator attempting
to write TRUNCATE action at position 4
> [18:06:25][Step 8/8] I0215 17:06:25.313807  1761 slave.cpp:3482] Received ping from slave-observer(360)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.313946  1754 master.cpp:4305] Registered slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
at slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io) with cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000]
> [18:06:25][Step 8/8] I0215 17:06:25.314067  1756 slave.cpp:971] Registered with master
master@172.30.2.239:39785; given slave ID 112363e2-c680-4946-8fee-d0626ed8b21e-S0
> [18:06:25][Step 8/8] I0215 17:06:25.314095  1756 fetcher.cpp:81] Clearing fetcher cache
> [18:06:25][Step 8/8] I0215 17:06:25.314102  1760 replica.cpp:537] Replica received write
request for position 4 from (13623)@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.314164  1758 hierarchical.cpp:473] Added slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
(ip-172-30-2-239.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
(allocated: )
> [18:06:25][Step 8/8] I0215 17:06:25.314219  1761 status_update_manager.cpp:181] Resuming
sending status updates
> [18:06:25][Step 8/8] I0215 17:06:25.314370  1756 slave.cpp:994] Checkpointing SlaveInfo
to '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/meta/slaves/112363e2-c680-4946-8fee-d0626ed8b21e-S0/slave.info'
> [18:06:25][Step 8/8] I0215 17:06:25.314579  1756 slave.cpp:1030] Forwarding total oversubscribed
resources 
> [18:06:25][Step 8/8] I0215 17:06:25.314707  1756 master.cpp:4646] Received update of
slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 at slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io)
with total oversubscribed resources 
> [18:06:25][Step 8/8] I0215 17:06:25.314818  1758 hierarchical.cpp:1498] No inverse offers
to send out!
> [18:06:25][Step 8/8] I0215 17:06:25.314848  1758 hierarchical.cpp:1116] Performed allocation
for slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 in 654176ns
> [18:06:25][Step 8/8] I0215 17:06:25.315137  1758 hierarchical.cpp:531] Slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
(ip-172-30-2-239.mesosphere.io) updated with oversubscribed resources  (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
> [18:06:25][Step 8/8] I0215 17:06:25.315217  1756 master.cpp:5352] Sending 1 offers to
framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 (default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.315238  1758 hierarchical.cpp:1403] No resources
available to allocate!
> [18:06:25][Step 8/8] I0215 17:06:25.315268  1758 hierarchical.cpp:1498] No inverse offers
to send out!
> [18:06:25][Step 8/8] I0215 17:06:25.315285  1758 hierarchical.cpp:1116] Performed allocation
for slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 in 118646ns
> [18:06:25][Step 8/8] I0215 17:06:25.315635  1755 sched.cpp:873] Scheduler::resourceOffers
took 99802ns
> [18:06:25][Step 8/8] I0215 17:06:25.317126  1755 master.cpp:3138] Processing ACCEPT call
for offers: [ 112363e2-c680-4946-8fee-d0626ed8b21e-O0 ] on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
at slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io) for framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
(default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:25][Step 8/8] I0215 17:06:25.317163  1755 master.cpp:2825] Authorizing framework
principal 'test-principal' to launch task 1 as user 'root'
> [18:06:25][Step 8/8] I0215 17:06:25.317229  1760 leveldb.cpp:341] Persisting action (16
bytes) to leveldb took 3.089068ms
> [18:06:25][Step 8/8] I0215 17:06:25.317261  1760 replica.cpp:712] Persisted action at
4
> [18:06:25][Step 8/8] I0215 17:06:25.317845  1759 replica.cpp:691] Replica received learned
notice for position 4 from @0.0.0.0:0
> [18:06:25][Step 8/8] I0215 17:06:25.318722  1755 master.hpp:176] Adding task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
(ip-172-30-2-239.mesosphere.io)
> [18:06:25][Step 8/8] I0215 17:06:25.318886  1755 master.cpp:3623] Launching task 1 of
framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 (default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
at slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io)
> [18:06:25][Step 8/8] I0215 17:06:25.319195  1757 slave.cpp:1361] Got assigned task 1
for framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:25][Step 8/8] I0215 17:06:25.319305  1759 leveldb.cpp:341] Persisting action (18
bytes) to leveldb took 1.430044ms
> [18:06:25][Step 8/8] I0215 17:06:25.319349  1757 resources.cpp:576] Parsing resources
as JSON failed: cpus:0.1;mem:32
> [18:06:25][Step 8/8] Trying semicolon-delimited string format instead
> [18:06:25][Step 8/8] I0215 17:06:25.319363  1759 leveldb.cpp:399] Deleting ~2 keys from
leveldb took 34738ns
> [18:06:25][Step 8/8] I0215 17:06:25.319380  1759 replica.cpp:712] Persisted action at
4
> [18:06:25][Step 8/8] I0215 17:06:25.319396  1759 replica.cpp:697] Replica learned TRUNCATE
action at position 4
> [18:06:25][Step 8/8] I0215 17:06:25.320034  1757 slave.cpp:1480] Launching task 1 for
framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:25][Step 8/8] I0215 17:06:25.320127  1757 resources.cpp:576] Parsing resources
as JSON failed: cpus:0.1;mem:32
> [18:06:25][Step 8/8] Trying semicolon-delimited string format instead
> [18:06:25][Step 8/8] I0215 17:06:25.320725  1757 paths.cpp:474] Trying to chown '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/slaves/112363e2-c680-4946-8fee-d0626ed8b21e-S0/frameworks/112363e2-c680-4946-8fee-d0626ed8b21e-0000/executors/1/runs/4f58cd28-7ac7-4960-b3e3-8d28918e6d08'
to user 'root'
> [18:06:25][Step 8/8] I0215 17:06:25.325739  1757 slave.cpp:5351] Launching executor 1
of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 with resources cpus(*):0.1; mem(*):32
in work directory '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/slaves/112363e2-c680-4946-8fee-d0626ed8b21e-S0/frameworks/112363e2-c680-4946-8fee-d0626ed8b21e-0000/executors/1/runs/4f58cd28-7ac7-4960-b3e3-8d28918e6d08'
> [18:06:25][Step 8/8] I0215 17:06:25.326493  1757 slave.cpp:1698] Queuing task '1' for
executor '1' of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:25][Step 8/8] I0215 17:06:25.326633  1757 slave.cpp:749] Successfully attached
file '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/slaves/112363e2-c680-4946-8fee-d0626ed8b21e-S0/frameworks/112363e2-c680-4946-8fee-d0626ed8b21e-0000/executors/1/runs/4f58cd28-7ac7-4960-b3e3-8d28918e6d08'
> [18:06:25][Step 8/8] I0215 17:06:25.331328  1761 docker.cpp:803] Starting container '4f58cd28-7ac7-4960-b3e3-8d28918e6d08'
for task '1' (and executor '1') of framework '112363e2-c680-4946-8fee-d0626ed8b21e-0000'
> [18:06:25][Step 8/8] I0215 17:06:25.331699  1761 docker.cpp:1053] Running docker -H unix:///var/run/docker.sock
inspect alpine:latest
> [18:06:25][Step 8/8] I0215 17:06:25.449668  1758 docker.cpp:384] Docker pull alpine completed
> [18:06:25][Step 8/8] I0215 17:06:25.511905  1760 slave.cpp:2643] Got registration for
executor '1' of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 from executor(1)@172.30.2.239:38602
> [18:06:25][Step 8/8] I0215 17:06:25.513098  1759 docker.cpp:1077] Ignoring updating container
'4f58cd28-7ac7-4960-b3e3-8d28918e6d08' with resources passed to update is identical to existing
resources
> [18:06:25][Step 8/8] I0215 17:06:25.513494  1756 slave.cpp:1863] Sending queued task
'1' to executor '1' of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 at executor(1)@172.30.2.239:38602
> [18:06:26][Step 8/8] 2016-02-15 17:06:25,981:1740(0x7f870b7fe700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:36716] zk retcode=-4, errno=111(Connection refused): server refused to accept
the client
> [18:06:26][Step 8/8] I0215 17:06:26.227973  1757 slave.cpp:3002] Handling status update
TASK_RUNNING (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
from executor(1)@172.30.2.239:38602
> [18:06:26][Step 8/8] I0215 17:06:26.228302  1757 slave.cpp:3002] Handling status update
TASK_FAILED (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
from executor(1)@172.30.2.239:38602
> [18:06:26][Step 8/8] I0215 17:06:26.228734  1754 status_update_manager.cpp:320] Received
status update TASK_RUNNING (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.228790  1754 status_update_manager.cpp:497] Creating
StatusUpdate stream for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.228837  1757 slave.cpp:5661] Terminating task 1
> [18:06:26][Step 8/8] I0215 17:06:26.229243  1754 status_update_manager.cpp:374] Forwarding
update TASK_RUNNING (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
to the slave
> [18:06:26][Step 8/8] I0215 17:06:26.229346  1755 docker.cpp:766] Running docker -H unix:///var/run/docker.sock
inspect mesos-112363e2-c680-4946-8fee-d0626ed8b21e-S0.4f58cd28-7ac7-4960-b3e3-8d28918e6d08
> [18:06:26][Step 8/8] I0215 17:06:26.232147  1758 slave.cpp:3400] Forwarding the update
TASK_RUNNING (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
to master@172.30.2.239:39785
> [18:06:26][Step 8/8] I0215 17:06:26.232383  1758 slave.cpp:3294] Status update manager
successfully handled status update TASK_RUNNING (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3)
for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.232419  1758 slave.cpp:3310] Sending acknowledgement
for status update TASK_RUNNING (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of
framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 to executor(1)@172.30.2.239:38602
> [18:06:26][Step 8/8] I0215 17:06:26.232631  1759 master.cpp:4791] Status update TASK_RUNNING
(UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
from slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 at slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io)
> [18:06:26][Step 8/8] I0215 17:06:26.232681  1759 master.cpp:4839] Forwarding status update
TASK_RUNNING (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.232911  1759 master.cpp:6447] Updating the state
of task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 (latest state: TASK_FAILED,
status update state: TASK_RUNNING)
> [18:06:26][Step 8/8] I0215 17:06:26.233170  1756 sched.cpp:981] Scheduler::statusUpdate
took 100304ns
> [18:06:26][Step 8/8] I0215 17:06:26.233613  1754 hierarchical.cpp:892] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: ) on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 from
framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.233642  1759 master.cpp:3949] Processing ACKNOWLEDGE
call b0f4bfb3-0f3c-4b03-843d-b5af82a902a3 for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
(default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785 on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
> [18:06:26][Step 8/8] I0215 17:06:26.233944  1759 status_update_manager.cpp:392] Received
status update acknowledgement (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3) for task 1 of framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.234294  1761 slave.cpp:2412] Status update manager
successfully handled status update acknowledgement (UUID: b0f4bfb3-0f3c-4b03-843d-b5af82a902a3)
for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.264482  1759 hierarchical.cpp:1498] No inverse offers
to send out!
> [18:06:26][Step 8/8] I0215 17:06:26.264554  1759 hierarchical.cpp:1096] Performed allocation
for 1 slaves in 1.210209ms
> [18:06:26][Step 8/8] I0215 17:06:26.264837  1757 master.cpp:5352] Sending 1 offers to
framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 (default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:26][Step 8/8] I0215 17:06:26.265275  1760 sched.cpp:873] Scheduler::resourceOffers
took 26245ns
> [18:06:26][Step 8/8] I0215 17:06:26.357859  1756 status_update_manager.cpp:320] Received
status update TASK_FAILED (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.358085  1756 status_update_manager.cpp:374] Forwarding
update TASK_FAILED (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
to the slave
> [18:06:26][Step 8/8] I0215 17:06:26.358330  1758 slave.cpp:3400] Forwarding the update
TASK_FAILED (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
to master@172.30.2.239:39785
> [18:06:26][Step 8/8] I0215 17:06:26.358554  1758 slave.cpp:3294] Status update manager
successfully handled status update TASK_FAILED (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2)
for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.358594  1758 slave.cpp:3310] Sending acknowledgement
for status update TASK_FAILED (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000 to executor(1)@172.30.2.239:38602
> [18:06:26][Step 8/8] I0215 17:06:26.358687  1761 master.cpp:4791] Status update TASK_FAILED
(UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
from slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 at slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io)
> [18:06:26][Step 8/8] I0215 17:06:26.358724  1761 master.cpp:4839] Forwarding status update
TASK_FAILED (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.358921  1761 master.cpp:6447] Updating the state
of task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 (latest state: TASK_FAILED,
status update state: TASK_FAILED)
> [18:06:26][Step 8/8] ../../src/tests/containerizer/docker_containerizer_tests.cpp:1269:
Failure
> [18:06:26][Step 8/8] I0215 17:06:26.359128  1754 sched.cpp:981] Scheduler::statusUpdate
took 108209ns
> [18:06:26][Step 8/8] Value of: statusFinished.get().state()
> [18:06:26][Step 8/8] I0215 17:06:26.359400  1759 master.cpp:3949] Processing ACKNOWLEDGE
call 05810f46-10e7-4d50-a83d-d05bf79dd8e2 for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
(default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785 on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0
> [18:06:26][Step 8/8]   Actual: TASK_FAILED
> [18:06:26][Step 8/8] Expected: TASK_FINISHED
> [18:06:26][Step 8/8] ../../src/tests/containerizer/docker_containerizer_tests.cpp:1278:
Failure
> [18:06:26][Step 8/8] I0215 17:06:26.359470  1759 master.cpp:6513] Removing task 1 with
resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 at slave(393)@172.30.2.239:39785 (ip-172-30-2-239.mesosphere.io)
> [18:06:26][Step 8/8] Value of: containsLine(lines, "err" + uuid)
> [18:06:26][Step 8/8]   Actual: false
> [18:06:26][Step 8/8] I0215 17:06:26.359928  1761 status_update_manager.cpp:392] Received
status update acknowledgement (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2) for task 1 of framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] Expected: true
> [18:06:26][Step 8/8] I0215 17:06:26.359931  1740 sched.cpp:1903] Asked to stop the driver
> [18:06:26][Step 8/8] ../../src/tests/containerizer/docker_containerizer_tests.cpp:1286:
Failure
> [18:06:26][Step 8/8] I0215 17:06:26.360031  1759 sched.cpp:1143] Stopping framework '112363e2-c680-4946-8fee-d0626ed8b21e-0000'
> [18:06:26][Step 8/8] Value of: containsLine(lines, "out" + uuid)
> [18:06:26][Step 8/8] I0215 17:06:26.360080  1761 status_update_manager.cpp:528] Cleaning
up status update stream for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8]   Actual: false
> [18:06:26][Step 8/8] Expected: true
> [18:06:26][Step 8/8] I0215 17:06:26.360213  1760 master.cpp:5923] Processing TEARDOWN
call for framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 (default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:26][Step 8/8] I0215 17:06:26.360239  1760 master.cpp:5935] Removing framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000 (default) at scheduler-806c70e3-1cf6-418f-aa30-6bb26db42d18@172.30.2.239:39785
> [18:06:26][Step 8/8] I0215 17:06:26.360481  1755 slave.cpp:2412] Status update manager
successfully handled status update acknowledgement (UUID: 05810f46-10e7-4d50-a83d-d05bf79dd8e2)
for task 1 of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.360522  1755 slave.cpp:5702] Completing task 1
> [18:06:26][Step 8/8] I0215 17:06:26.360539  1756 hierarchical.cpp:375] Deactivated framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.360586  1755 slave.cpp:2079] Asked to shut down framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000 by master@172.30.2.239:39785
> [18:06:26][Step 8/8] I0215 17:06:26.360610  1755 slave.cpp:2104] Shutting down framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.360666  1755 slave.cpp:4198] Shutting down executor
'1' of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 at executor(1)@172.30.2.239:38602
> [18:06:26][Step 8/8] I0215 17:06:26.361110  1761 hierarchical.cpp:892] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: ) on slave 112363e2-c680-4946-8fee-d0626ed8b21e-S0 from
framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.361395  1756 hierarchical.cpp:326] Removed framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.361397  1760 master.cpp:1027] Master terminating
> [18:06:26][Step 8/8] I0215 17:06:26.361800  1755 hierarchical.cpp:505] Removed slave
112363e2-c680-4946-8fee-d0626ed8b21e-S0
> [18:06:26][Step 8/8] I0215 17:06:26.362174  1756 slave.cpp:3528] master@172.30.2.239:39785
exited
> [18:06:26][Step 8/8] W0215 17:06:26.362200  1756 slave.cpp:3531] Master disconnected!
Waiting for a new master to be elected
> [18:06:26][Step 8/8] I0215 17:06:26.367146  1758 docker.cpp:1455] Destroying container
'4f58cd28-7ac7-4960-b3e3-8d28918e6d08'
> [18:06:26][Step 8/8] I0215 17:06:26.367168  1758 docker.cpp:1515] Sending SIGTERM to
executor with pid: 10194
> [18:06:26][Step 8/8] I0215 17:06:26.383013  1758 docker.cpp:1557] Running docker stop
on container '4f58cd28-7ac7-4960-b3e3-8d28918e6d08'
> [18:06:26][Step 8/8] I0215 17:06:26.384843  1757 slave.cpp:3528] executor(1)@172.30.2.239:38602
exited
> [18:06:26][Step 8/8] I0215 17:06:26.458639  1761 docker.cpp:1654] Executor for container
'4f58cd28-7ac7-4960-b3e3-8d28918e6d08' has exited
> [18:06:26][Step 8/8] I0215 17:06:26.458806  1757 slave.cpp:3886] Executor '1' of framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000 terminated with signal Terminated
> [18:06:26][Step 8/8] I0215 17:06:26.458852  1757 slave.cpp:3990] Cleaning up executor
'1' of framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000 at executor(1)@172.30.2.239:38602
> [18:06:26][Step 8/8] I0215 17:06:26.459166  1754 gc.cpp:54] Scheduling '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/slaves/112363e2-c680-4946-8fee-d0626ed8b21e-S0/frameworks/112363e2-c680-4946-8fee-d0626ed8b21e-0000/executors/1/runs/4f58cd28-7ac7-4960-b3e3-8d28918e6d08'
for gc 6.99999468745481days in the future
> [18:06:26][Step 8/8] I0215 17:06:26.459262  1757 slave.cpp:4078] Cleaning up framework
112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.459336  1754 gc.cpp:54] Scheduling '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/slaves/112363e2-c680-4946-8fee-d0626ed8b21e-S0/frameworks/112363e2-c680-4946-8fee-d0626ed8b21e-0000/executors/1'
for gc 6.99999468505778days in the future
> [18:06:26][Step 8/8] I0215 17:06:26.459372  1761 status_update_manager.cpp:282] Closing
status update streams for framework 112363e2-c680-4946-8fee-d0626ed8b21e-0000
> [18:06:26][Step 8/8] I0215 17:06:26.459481  1754 gc.cpp:54] Scheduling '/tmp/DockerContainerizerTest_ROOT_DOCKER_Logs_a4NS2N/slaves/112363e2-c680-4946-8fee-d0626ed8b21e-S0/frameworks/112363e2-c680-4946-8fee-d0626ed8b21e-0000'
for gc 6.99999468310222days in the future
> [18:06:26][Step 8/8] I0215 17:06:26.459915  1759 slave.cpp:668] Slave terminating
> [18:06:26][Step 8/8] I0215 17:06:26.463074  1740 docker.cpp:885] Running docker -H unix:///var/run/docker.sock
ps -a
> [18:06:26][Step 8/8] I0215 17:06:26.560154  1760 docker.cpp:766] Running docker -H unix:///var/run/docker.sock
inspect mesos-112363e2-c680-4946-8fee-d0626ed8b21e-S0.4f58cd28-7ac7-4960-b3e3-8d28918e6d08
> [18:06:26][Step 8/8] I0215 17:06:26.666368  1740 docker.cpp:727] Running docker -H unix:///var/run/docker.sock
rm -f -v c7f89c245f256c03222551178f6a0c26413bb91dfb3c843bff837b365d7c7432
> [18:06:26][Step 8/8] [  FAILED  ] DockerContainerizerTest.ROOT_DOCKER_Logs (1519 ms)
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message