[
https://issues.apache.org/jira/browse/MESOS-4810?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Artem Harutyunyan updated MESOS-4810:
-------------------------------------
Sprint: Mesosphere Sprint 30, Mesosphere Sprint 31 (was: Mesosphere Sprint
30)
> ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand fails.
> --------------------------------------------------------------------------
>
> Key: MESOS-4810
> URL: https://issues.apache.org/jira/browse/MESOS-4810
> Project: Mesos
> Issue Type: Bug
> Components: docker
> Affects Versions: 0.28.0
> Environment: CentOS 7 on AWS, both with or without SSL.
> Reporter: Bernd Mathiske
> Assignee: Jie Yu
> Labels: docker, mesosphere, test
>
> {noformat}
> [09:46:46] : [Step 11/11] [ RUN ]
> ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand
> [09:46:46]W: [Step 11/11] I0229 09:46:46.628413 1166 leveldb.cpp:174]
> Opened db in 4.242882ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.629926 1166 leveldb.cpp:181]
> Compacted db in 1.483621ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.629966 1166 leveldb.cpp:196]
> Created db iterator in 15498ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.629977 1166 leveldb.cpp:202]
> Seeked to beginning of db in 1405ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.629984 1166 leveldb.cpp:271]
> Iterated through 0 keys in the db in 239ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.630015 1166 replica.cpp:779]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [09:46:46]W: [Step 11/11] I0229 09:46:46.630470 1183 recover.cpp:447]
> Starting replica recovery
> [09:46:46]W: [Step 11/11] I0229 09:46:46.630702 1180 recover.cpp:473]
> Replica is in EMPTY status
> [09:46:46]W: [Step 11/11] I0229 09:46:46.631767 1182 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> (14567)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.632115 1183 recover.cpp:193]
> Received a recover response from a replica in EMPTY status
> [09:46:46]W: [Step 11/11] I0229 09:46:46.632450 1186 recover.cpp:564]
> Updating replica status to STARTING
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633476 1186 master.cpp:375]
> Master 3fbb2fb0-4f18-498b-a440-9acbf6923a13 (ip-172-30-2-124.mesosphere.io)
> started on 172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633491 1186 master.cpp:377] Flags
> at startup: --acls="" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate="true"
> --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/4UxXoW/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/4UxXoW/master"
> --zk_session_timeout="10secs"
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633677 1186 master.cpp:422]
> Master only allowing authenticated frameworks to register
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633685 1186 master.cpp:427]
> Master only allowing authenticated slaves to register
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633692 1186 credentials.hpp:35]
> Loading credentials for authentication from '/tmp/4UxXoW/credentials'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633851 1183 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.191043ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633873 1183 replica.cpp:320]
> Persisted replica status to STARTING
> [09:46:46]W: [Step 11/11] I0229 09:46:46.633894 1186 master.cpp:467] Using
> default 'crammd5' authenticator
> [09:46:46]W: [Step 11/11] I0229 09:46:46.634003 1186 master.cpp:536] Using
> default 'basic' HTTP authenticator
> [09:46:46]W: [Step 11/11] I0229 09:46:46.634062 1184 recover.cpp:473]
> Replica is in STARTING status
> [09:46:46]W: [Step 11/11] I0229 09:46:46.634109 1186 master.cpp:570]
> Authorization enabled
> [09:46:46]W: [Step 11/11] I0229 09:46:46.634249 1187
> whitelist_watcher.cpp:77] No whitelist given
> [09:46:46]W: [Step 11/11] I0229 09:46:46.634255 1184 hierarchical.cpp:144]
> Initialized hierarchical allocator process
> [09:46:46]W: [Step 11/11] I0229 09:46:46.634884 1187 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> (14569)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.635278 1181 recover.cpp:193]
> Received a recover response from a replica in STARTING status
> [09:46:46]W: [Step 11/11] I0229 09:46:46.635742 1187 recover.cpp:564]
> Updating replica status to VOTING
> [09:46:46]W: [Step 11/11] I0229 09:46:46.636391 1180 master.cpp:1711] The
> newly elected leader is [email protected]:37431 with id
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13
> [09:46:46]W: [Step 11/11] I0229 09:46:46.636415 1180 master.cpp:1724]
> Elected as the leading master!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.636430 1180 master.cpp:1469]
> Recovering from registrar
> [09:46:46]W: [Step 11/11] I0229 09:46:46.636554 1187 registrar.cpp:307]
> Recovering registrar
> [09:46:46]W: [Step 11/11] I0229 09:46:46.637111 1181 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.120322ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.637133 1181 replica.cpp:320]
> Persisted replica status to VOTING
> [09:46:46]W: [Step 11/11] I0229 09:46:46.637218 1186 recover.cpp:578]
> Successfully joined the Paxos group
> [09:46:46]W: [Step 11/11] I0229 09:46:46.637354 1186 recover.cpp:462]
> Recover process terminated
> [09:46:46]W: [Step 11/11] I0229 09:46:46.637715 1182 log.cpp:659]
> Attempting to start the writer
> [09:46:46]W: [Step 11/11] I0229 09:46:46.638617 1184 replica.cpp:493]
> Replica received implicit promise request from (14570)@172.30.2.124:37431
> with proposal 1
> [09:46:46]W: [Step 11/11] I0229 09:46:46.639700 1184 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.057386ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.639722 1184 replica.cpp:342]
> Persisted promised to 1
> [09:46:46]W: [Step 11/11] I0229 09:46:46.640251 1184 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [09:46:46]W: [Step 11/11] I0229 09:46:46.641274 1185 replica.cpp:388]
> Replica received explicit promise request from (14571)@172.30.2.124:37431 for
> position 0 with proposal 2
> [09:46:46]W: [Step 11/11] I0229 09:46:46.642371 1185 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 1.061574ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.642396 1185 replica.cpp:712]
> Persisted action at 0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.643299 1186 replica.cpp:537]
> Replica received write request for position 0 from (14572)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.643349 1186 leveldb.cpp:436]
> Reading position from leveldb took 21735ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.644448 1186 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 1.06671ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.644469 1186 replica.cpp:712]
> Persisted action at 0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.645077 1181 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.646174 1181 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.069097ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.646198 1181 replica.cpp:712]
> Persisted action at 0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.646211 1181 replica.cpp:697]
> Replica learned NOP action at position 0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.646716 1182 log.cpp:675] Writer
> started with ending position 0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.647538 1183 leveldb.cpp:436]
> Reading position from leveldb took 21456ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.648298 1186 registrar.cpp:340]
> Successfully fetched the registry (0B) in 11.71072ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.648388 1186 registrar.cpp:439]
> Applied 1 operations in 21138ns; attempting to update the 'registry'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.648947 1187 log.cpp:683]
> Attempting to append 210 bytes to the log
> [09:46:46]W: [Step 11/11] I0229 09:46:46.649050 1183 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [09:46:46]W: [Step 11/11] I0229 09:46:46.649655 1187 replica.cpp:537]
> Replica received write request for position 1 from (14573)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.650725 1187 leveldb.cpp:341]
> Persisting action (229 bytes) to leveldb took 1.041938ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.650748 1187 replica.cpp:712]
> Persisted action at 1
> [09:46:46]W: [Step 11/11] I0229 09:46:46.651198 1181 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.652312 1181 leveldb.cpp:341]
> Persisting action (231 bytes) to leveldb took 1.092268ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.652335 1181 replica.cpp:712]
> Persisted action at 1
> [09:46:46]W: [Step 11/11] I0229 09:46:46.652349 1181 replica.cpp:697]
> Replica learned APPEND action at position 1
> [09:46:46]W: [Step 11/11] I0229 09:46:46.653095 1187 registrar.cpp:484]
> Successfully updated the 'registry' in 4.664064ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.653236 1187 registrar.cpp:370]
> Successfully recovered registrar
> [09:46:46]W: [Step 11/11] I0229 09:46:46.653306 1181 log.cpp:702]
> Attempting to truncate the log to 1
> [09:46:46]W: [Step 11/11] I0229 09:46:46.653476 1184 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [09:46:46]W: [Step 11/11] I0229 09:46:46.653642 1183 master.cpp:1521]
> Recovered 0 slaves from the Registry (171B) ; allowing 10mins for slaves to
> re-register
> [09:46:46]W: [Step 11/11] I0229 09:46:46.653659 1181 hierarchical.cpp:171]
> Skipping recovery of hierarchical allocator: nothing to recover
> [09:46:46]W: [Step 11/11] I0229 09:46:46.654270 1181 replica.cpp:537]
> Replica received write request for position 2 from (14574)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.655357 1181 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.055267ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.655378 1181 replica.cpp:712]
> Persisted action at 2
> [09:46:46]W: [Step 11/11] I0229 09:46:46.655850 1184 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.657009 1184 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.137223ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.657059 1184 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 26459ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.657074 1184 replica.cpp:712]
> Persisted action at 2
> [09:46:46]W: [Step 11/11] I0229 09:46:46.657089 1184 replica.cpp:697]
> Replica learned TRUNCATE action at position 2
> [09:46:46]W: [Step 11/11] I0229 09:46:46.665710 1166
> containerizer.cpp:149] Using isolation: docker/runtime,filesystem/linux
> [09:46:46]W: [Step 11/11] I0229 09:46:46.672399 1166
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
> for the Linux launcher
> [09:46:46]W: [Step 11/11] E0229 09:46:46.676822 1166 shell.hpp:93] Command
> 'hadoop version 2>&1' failed; this is the output:
> [09:46:46]W: [Step 11/11] sh: hadoop: command not found
> [09:46:46]W: [Step 11/11] E0229 09:46:46.676851 1166 fetcher.cpp:58]
> Failed to create URI fetcher plugin 'hadoop': Failed to create HDFS client:
> Failed to execute 'hadoop version 2>&1'; the command was either not found or
> exited with a non-zero exit status: 127
> [09:46:46]W: [Step 11/11] I0229 09:46:46.678383 1166 linux.cpp:81] Making
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv'
> a shared mount
> [09:46:46]W: [Step 11/11] I0229 09:46:46.687223 1180 slave.cpp:193] Slave
> started on 422)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.687248 1180 slave.cpp:194] Flags
> at startup: --appc_simple_discovery_uri_prefix="http://";
> --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/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/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"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --image_providers="docker"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="docker/runtime,filesystem/linux"
> --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_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv"
> [09:46:46]W: [Step 11/11] I0229 09:46:46.687531 1180 credentials.hpp:83]
> Loading credential for authentication from
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/credential'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.687666 1180 slave.cpp:324] Slave
> using credential for: test-principal
> [09:46:46]W: [Step 11/11] I0229 09:46:46.687798 1180 resources.cpp:572]
> Parsing resources as JSON failed:
> cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> [09:46:46]W: [Step 11/11] Trying semicolon-delimited string format instead
> [09:46:46]W: [Step 11/11] I0229 09:46:46.688151 1180 slave.cpp:464] Slave
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [09:46:46]W: [Step 11/11] I0229 09:46:46.688207 1180 slave.cpp:472] Slave
> attributes: [ ]
> [09:46:46]W: [Step 11/11] I0229 09:46:46.688217 1180 slave.cpp:477] Slave
> hostname: ip-172-30-2-124.mesosphere.io
> [09:46:46]W: [Step 11/11] I0229 09:46:46.689259 1187 state.cpp:58]
> Recovering state from
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/meta'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.689394 1166 sched.cpp:222]
> Version: 0.28.0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.689497 1180
> status_update_manager.cpp:200] Recovering status update manager
> [09:46:46]W: [Step 11/11] I0229 09:46:46.689798 1182
> containerizer.cpp:407] Recovering containerizer
> [09:46:46]W: [Step 11/11] I0229 09:46:46.690021 1186 sched.cpp:326] New
> master detected at [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.690146 1186 sched.cpp:382]
> Authenticating with master [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.690162 1186 sched.cpp:389] Using
> default CRAM-MD5 authenticatee
> [09:46:46]W: [Step 11/11] I0229 09:46:46.690378 1181
> authenticatee.cpp:121] Creating new client SASL connection
> [09:46:46]W: [Step 11/11] I0229 09:46:46.690688 1186 master.cpp:5540]
> Authenticating
> [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.690801 1184
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(877)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691025 1181 authenticator.cpp:98]
> Creating new server SASL connection
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691314 1180
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691339 1180
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691437 1180
> authenticator.cpp:203] Received SASL authentication start
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691490 1180
> authenticator.cpp:325] Authentication requires more steps
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691581 1180
> authenticatee.cpp:258] Received SASL authentication step
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691684 1180
> authenticator.cpp:231] Received SASL authentication step
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691712 1180 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-124.mesosphere.io' server FQDN: 'ip-172-30-2-124.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691726 1180 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691768 1180 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691802 1180 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-124.mesosphere.io' server FQDN: 'ip-172-30-2-124.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691817 1180 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691829 1180 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691848 1180
> authenticator.cpp:317] Authentication success
> [09:46:46]W: [Step 11/11] I0229 09:46:46.691944 1186
> authenticatee.cpp:298] Authentication success
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692011 1185 master.cpp:5570]
> Successfully authenticated principal 'test-principal' at
> [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692056 1187
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(877)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692308 1184 sched.cpp:471]
> Successfully authenticated with master [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692325 1184 sched.cpp:776]
> Sending SUBSCRIBE call to [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692399 1184 sched.cpp:809] Will
> retry registration in 954.231367ms if necessary
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692505 1183 master.cpp:2279]
> Received SUBSCRIBE call for framework 'default' at
> [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692553 1183 master.cpp:1750]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692836 1184 master.cpp:2350]
> Subscribing framework default with checkpointing disabled and capabilities [
> ]
> [09:46:46]W: [Step 11/11] I0229 09:46:46.692942 1183
> metadata_manager.cpp:188] No images to load from disk. Docker provisioner
> image storage path '/tmp/mesos/store/docker/storedImages' does not exist
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693208 1180 provisioner.cpp:245]
> Provisioner recovery complete
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693295 1186 hierarchical.cpp:265]
> Added framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693357 1186
> hierarchical.cpp:1437] No resources available to allocate!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693397 1186
> hierarchical.cpp:1532] No inverse offers to send out!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693424 1186
> hierarchical.cpp:1130] Performed allocation for 0 slaves in 111679ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693442 1187 sched.cpp:703]
> Framework registered with 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693476 1187 sched.cpp:717]
> Scheduler::registered took 15735ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693604 1183 slave.cpp:4565]
> Finished recovery
> [09:46:46]W: [Step 11/11] I0229 09:46:46.693872 1183 slave.cpp:4737]
> Querying resource estimator for oversubscribable resources
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694072 1183 slave.cpp:796] New
> master detected at [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694078 1182
> status_update_manager.cpp:174] Pausing sending status updates
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694133 1183 slave.cpp:859]
> Authenticating with master [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694159 1183 slave.cpp:864] Using
> default CRAM-MD5 authenticatee
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694279 1183 slave.cpp:832]
> Detecting new master
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694320 1180
> authenticatee.cpp:121] Creating new client SASL connection
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694438 1183 slave.cpp:4751]
> Received oversubscribable resources from the resource estimator
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694577 1183 master.cpp:5540]
> Authenticating slave(422)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694659 1181
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(878)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.694840 1182 authenticator.cpp:98]
> Creating new server SASL connection
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695081 1187
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695109 1187
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695215 1186
> authenticator.cpp:203] Received SASL authentication start
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695257 1186
> authenticator.cpp:325] Authentication requires more steps
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695322 1186
> authenticatee.cpp:258] Received SASL authentication step
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695423 1185
> authenticator.cpp:231] Received SASL authentication step
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695446 1185 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-124.mesosphere.io' server FQDN: 'ip-172-30-2-124.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695453 1185 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695477 1185 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695497 1185 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-124.mesosphere.io' server FQDN: 'ip-172-30-2-124.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695504 1185 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695510 1185 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695520 1185
> authenticator.cpp:317] Authentication success
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695588 1180
> authenticatee.cpp:298] Authentication success
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695633 1186 master.cpp:5570]
> Successfully authenticated principal 'test-principal' at
> slave(422)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695675 1180
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(878)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.695933 1187 slave.cpp:927]
> Successfully authenticated with master [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.696039 1187 slave.cpp:1321] Will
> retry registration in 6.094985ms if necessary
> [09:46:46]W: [Step 11/11] I0229 09:46:46.696171 1183 master.cpp:4254]
> Registering slave at slave(422)@172.30.2.124:37431
> (ip-172-30-2-124.mesosphere.io) with id
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.696535 1181 registrar.cpp:439]
> Applied 1 operations in 48295ns; attempting to update the 'registry'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.697289 1182 log.cpp:683]
> Attempting to append 396 bytes to the log
> [09:46:46]W: [Step 11/11] I0229 09:46:46.697402 1183 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [09:46:46]W: [Step 11/11] I0229 09:46:46.698032 1181 replica.cpp:537]
> Replica received write request for position 3 from (14593)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.699445 1181 leveldb.cpp:341]
> Persisting action (415 bytes) to leveldb took 1.381647ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.699467 1181 replica.cpp:712]
> Persisted action at 3
> [09:46:46]W: [Step 11/11] I0229 09:46:46.699934 1181 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.701073 1181 leveldb.cpp:341]
> Persisting action (417 bytes) to leveldb took 1.117397ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.701095 1181 replica.cpp:712]
> Persisted action at 3
> [09:46:46]W: [Step 11/11] I0229 09:46:46.701110 1181 replica.cpp:697]
> Replica learned APPEND action at position 3
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702229 1185 registrar.cpp:484]
> Successfully updated the 'registry' in 5.643008ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702409 1182 log.cpp:702]
> Attempting to truncate the log to 3
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702441 1180 slave.cpp:1321] Will
> retry registration in 33.795772ms if necessary
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702523 1181 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702775 1182 slave.cpp:3482]
> Received ping from slave-observer(389)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702837 1184 master.cpp:4322]
> Registered slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at
> slave(422)@172.30.2.124:37431 (ip-172-30-2-124.mesosphere.io) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702922 1182 slave.cpp:971]
> Registered with master [email protected]:37431; given slave ID
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.702947 1182 fetcher.cpp:81]
> Clearing fetcher cache
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703011 1181 hierarchical.cpp:473]
> Added slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> (ip-172-30-2-124.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (allocated: )
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703053 1184 master.cpp:4224]
> Slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at
> slave(422)@172.30.2.124:37431 (ip-172-30-2-124.mesosphere.io) already
> registered, resending acknowledgement
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703060 1186
> status_update_manager.cpp:181] Resuming sending status updates
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703213 1184 replica.cpp:537]
> Replica received write request for position 4 from (14594)@172.30.2.124:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703228 1182 slave.cpp:994]
> Checkpointing SlaveInfo to
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/meta/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/slave.info'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703416 1182 slave.cpp:1030]
> Forwarding total oversubscribed resources
> [09:46:46]W: [Step 11/11] W0229 09:46:46.703513 1182 slave.cpp:1016]
> Already registered with master [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703531 1182 slave.cpp:1030]
> Forwarding total oversubscribed resources
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703559 1185 master.cpp:4663]
> Received update of slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at
> slave(422)@172.30.2.124:37431 (ip-172-30-2-124.mesosphere.io) with total
> oversubscribed resources
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703564 1181
> hierarchical.cpp:1532] No inverse offers to send out!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703614 1181
> hierarchical.cpp:1150] Performed allocation for slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 in 572661ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703939 1185 master.cpp:5369]
> Sending 1 offers to framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> (default) at [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.703972 1186 hierarchical.cpp:531]
> Slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 (ip-172-30-2-124.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])
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704087 1186
> hierarchical.cpp:1437] No resources available to allocate!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704113 1185 master.cpp:4663]
> Received update of slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at
> slave(422)@172.30.2.124:37431 (ip-172-30-2-124.mesosphere.io) with total
> oversubscribed resources
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704123 1186
> hierarchical.cpp:1532] No inverse offers to send out!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704169 1186
> hierarchical.cpp:1150] Performed allocation for slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 in 162818ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704421 1184 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.177949ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704442 1187 sched.cpp:873]
> Scheduler::resourceOffers took 146551ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704452 1184 replica.cpp:712]
> Persisted action at 4
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704747 1166 resources.cpp:572]
> Parsing resources as JSON failed: cpus:1;mem:128
> [09:46:46]W: [Step 11/11] Trying semicolon-delimited string format instead
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704737 1185 hierarchical.cpp:531]
> Slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 (ip-172-30-2-124.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])
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704888 1185
> hierarchical.cpp:1437] No resources available to allocate!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704931 1185
> hierarchical.cpp:1532] No inverse offers to send out!
> [09:46:46]W: [Step 11/11] I0229 09:46:46.704958 1185
> hierarchical.cpp:1150] Performed allocation for slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 in 172983ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.705059 1185 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [09:46:46]W: [Step 11/11] I0229 09:46:46.705976 1184 master.cpp:3152]
> Processing ACCEPT call for offers: [ 3fbb2fb0-4f18-498b-a440-9acbf6923a13-O0
> ] on slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at
> slave(422)@172.30.2.124:37431 (ip-172-30-2-124.mesosphere.io) for framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (default) at
> [email protected]:37431
> [09:46:46]W: [Step 11/11] I0229 09:46:46.706009 1184 master.cpp:2824]
> Authorizing framework principal 'test-principal' to launch task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 as user 'root'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.706212 1185 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.125309ms
> [09:46:46]W: [Step 11/11] I0229 09:46:46.706269 1185 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 32428ns
> [09:46:46]W: [Step 11/11] I0229 09:46:46.706284 1185 replica.cpp:712]
> Persisted action at 4
> [09:46:46]W: [Step 11/11] I0229 09:46:46.706298 1185 replica.cpp:697]
> Replica learned TRUNCATE action at position 4
> [09:46:46]W: [Step 11/11] I0229 09:46:46.707129 1184 master.hpp:176]
> Adding task cd81ece8-93b2-4e8a-a4b0-b566038bf281 with resources cpus(*):1;
> mem(*):128 on slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> (ip-172-30-2-124.mesosphere.io)
> [09:46:46]W: [Step 11/11] I0229 09:46:46.707231 1184 master.cpp:3637]
> Launching task cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (default) at
> [email protected]:37431 with
> resources cpus(*):1; mem(*):128 on slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at slave(422)@172.30.2.124:37431
> (ip-172-30-2-124.mesosphere.io)
> [09:46:46]W: [Step 11/11] I0229 09:46:46.707516 1182 slave.cpp:1361] Got
> assigned task cd81ece8-93b2-4e8a-a4b0-b566038bf281 for framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:46]W: [Step 11/11] I0229 09:46:46.707669 1182 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [09:46:46]W: [Step 11/11] Trying semicolon-delimited string format instead
> [09:46:46]W: [Step 11/11] I0229 09:46:46.707772 1183 hierarchical.cpp:890]
> Recovered cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] (total:
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated:
> cpus(*):1; mem(*):128) on slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 from
> framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:46]W: [Step 11/11] I0229 09:46:46.707814 1183 hierarchical.cpp:927]
> Framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 filtered slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 for 5secs
> [09:46:46]W: [Step 11/11] I0229 09:46:46.708055 1182 slave.cpp:1480]
> Launching task cd81ece8-93b2-4e8a-a4b0-b566038bf281 for framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:46]W: [Step 11/11] I0229 09:46:46.708122 1182 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [09:46:46]W: [Step 11/11] Trying semicolon-delimited string format instead
> [09:46:46]W: [Step 11/11] I0229 09:46:46.708601 1182 paths.cpp:474] Trying
> to chown
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/frameworks/3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000/executors/cd81ece8-93b2-4e8a-a4b0-b566038bf281/runs/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89'
> to user 'root'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.713331 1182 slave.cpp:5367]
> Launching executor cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/frameworks/3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000/executors/cd81ece8-93b2-4e8a-a4b0-b566038bf281/runs/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.713762 1185
> containerizer.cpp:666] Starting container
> '7f271a3f-bada-4dfb-a37f-f6c6d7aefd89' for executor
> 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' of framework
> '3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000'
> [09:46:46]W: [Step 11/11] I0229 09:46:46.713769 1182 slave.cpp:1698]
> Queuing task 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' for executor
> 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:46]W: [Step 11/11] I0229 09:46:46.713860 1182 slave.cpp:749]
> Successfully attached file
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/frameworks/3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000/executors/cd81ece8-93b2-4e8a-a4b0-b566038bf281/runs/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89'
> [09:46:47]W: [Step 11/11] I0229 09:46:47.601546 1180
> registry_puller.cpp:210] The manifest for image 'library/alpine' is '{
> [09:46:47]W: [Step 11/11] "schemaVersion": 1,
> [09:46:47]W: [Step 11/11] "name": "library/alpine",
> [09:46:47]W: [Step 11/11] "tag": "latest",
> [09:46:47]W: [Step 11/11] "architecture": "amd64",
> [09:46:47]W: [Step 11/11] "fsLayers": [
> [09:46:47]W: [Step 11/11] {
> [09:46:47]W: [Step 11/11] "blobSum":
> "sha256:ee54741ab35b188477c19fddc30356317b091177966da94c2e9391de49fc7f43"
> [09:46:47]W: [Step 11/11] }
> [09:46:47]W: [Step 11/11] ],
> [09:46:47]W: [Step 11/11] "history": [
> [09:46:47]W: [Step 11/11] {
> [09:46:47]W: [Step 11/11] "v1Compatibility":
> "{\"id\":\"9d710148acd0066166bf3ce04894072b2f3caed24d0295ae2fa136fb7f602605\",\"created\":\"2016-02-17T15:51:37.348814441Z\",\"container\":\"1c7d9aa5eff83e7f7e563f36c01ba975b90a4a6e17fa6024f4a998f5f0a43b28\",\"container_config\":{\"Hostname\":\"1c7d9aa5eff8\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":null,\"Cmd\":[\"/bin/sh\",\"-c\",\"#(nop)
> ADD file:0f9cfb2e848f093649aca9cc67927e4d04a74e150e0d92f4ad18ee583a287bf2 in
> /\"],\"Image\":\"\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":null,\"Labels\":null},\"docker_version\":\"1.9.1\",\"config\":{\"Hostname\":\"1c7d9aa5eff8\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":null,\"Cmd\":null,\"Image\":\"\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":null,\"Labels\":null},\"architecture\":\"amd64\",\"os\":\"linux\",\"Size\":4793867}"
> [09:46:47]W: [Step 11/11] }
> [09:46:47]W: [Step 11/11] ],
> [09:46:47]W: [Step 11/11] "signatures": [
> [09:46:47]W: [Step 11/11] {
> [09:46:47]W: [Step 11/11] "header": {
> [09:46:47]W: [Step 11/11] "jwk": {
> [09:46:47]W: [Step 11/11] "crv": "P-256",
> [09:46:47]W: [Step 11/11] "kid":
> "OOI5:SI3T:LC7D:O7DX:FY6S:IAYW:WDRN:VQEM:BCFL:OIST:Q3LO:GTQQ",
> [09:46:47]W: [Step 11/11] "kty": "EC",
> [09:46:47]W: [Step 11/11] "x":
> "J2N5ePGhlblMI2cdsR6NrAG_xbNC_X7s1HRtk5GXvzM",
> [09:46:47]W: [Step 11/11] "y":
> "Idr-tEBjnNnfq6_71aeXBi3Z9ah_rrE209l4wiaohk0"
> [09:46:47]W: [Step 11/11] },
> [09:46:47]W: [Step 11/11] "alg": "ES256"
> [09:46:47]W: [Step 11/11] },
> [09:46:47]W: [Step 11/11] "signature":
> "gFqNfRROAFCbMmm7sCjaNFjy18vu3IWQUrFQbhCwrpNuNbMc7ImdW636Pz1IrVfGTzalAZftluLsiHcMPU2jBQ",
> [09:46:47]W: [Step 11/11] "protected":
> "eyJmb3JtYXRMZW5ndGgiOjEzNzUsImZvcm1hdFRhaWwiOiJDbjAiLCJ0aW1lIjoiMjAxNi0wMi0yM1QxOTowMjowMFoifQ"
> [09:46:47]W: [Step 11/11] }
> [09:46:47]W: [Step 11/11] ]
> [09:46:47]W: [Step 11/11] }'
> [09:46:47]W: [Step 11/11] I0229 09:46:47.601771 1180
> registry_puller.cpp:317] Fetching blob
> 'sha256:ee54741ab35b188477c19fddc30356317b091177966da94c2e9391de49fc7f43' for
> layer '9d710148acd0066166bf3ce04894072b2f3caed24d0295ae2fa136fb7f602605' of
> image 'library/alpine'
> [09:46:47]W: [Step 11/11] I0229 09:46:47.635748 1182
> hierarchical.cpp:1623] Filtered offer with cpus(*):1; mem(*):896;
> disk(*):1024; ports(*):[31000-32000] on slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 for framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:47]W: [Step 11/11] I0229 09:46:47.635797 1182
> hierarchical.cpp:1437] No resources available to allocate!
> [09:46:47]W: [Step 11/11] I0229 09:46:47.635829 1182
> hierarchical.cpp:1532] No inverse offers to send out!
> [09:46:47]W: [Step 11/11] I0229 09:46:47.635854 1182
> hierarchical.cpp:1130] Performed allocation for 1 slaves in 573296ns
> [09:46:48]W: [Step 11/11] I0229 09:46:48.299258 1180 provisioner.cpp:285]
> Provisioning image rootfs
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/provisioner/containers/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89/backends/copy/rootfses/6f8be9d5-12fe-4b66-9ff3-fda1efbb2519'
> for container 7f271a3f-bada-4dfb-a37f-f6c6d7aefd89
> [09:46:48]W: [Step 11/11] I0229 09:46:48.299828 1181 copy.cpp:127] Copying
> layer path
> '/tmp/mesos/store/docker/layers/9d710148acd0066166bf3ce04894072b2f3caed24d0295ae2fa136fb7f602605/rootfs'
> to rootfs
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/provisioner/containers/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89/backends/copy/rootfses/6f8be9d5-12fe-4b66-9ff3-fda1efbb2519'
> [09:46:48]W: [Step 11/11] I0229 09:46:48.410997 1187
> linux_launcher.cpp:304] Cloning child process with flags = CLONE_NEWNS
> [09:46:48]W: [Step 11/11] +
> /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer mount
> --help=false --operation=make-rslave --path=/
> [09:46:48]W: [Step 11/11] + grep -E
> /tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/.+
> /proc/self/mountinfo
> [09:46:48]W: [Step 11/11] + grep -v 7f271a3f-bada-4dfb-a37f-f6c6d7aefd89
> [09:46:48]W: [Step 11/11] + cut '-d ' -f5
> [09:46:48]W: [Step 11/11] + xargs --no-run-if-empty umount -l
> [09:46:48]W: [Step 11/11] + mount -n --rbind
> /tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/provisioner/containers/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89/backends/copy/rootfses/6f8be9d5-12fe-4b66-9ff3-fda1efbb2519
>
> /tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/frameworks/3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000/executors/cd81ece8-93b2-4e8a-a4b0-b566038bf281/runs/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89/.rootfs
> [09:46:48]W: [Step 11/11] WARNING: Logging before InitGoogleLogging() is
> written to STDERR
> [09:46:48]W: [Step 11/11] I0229 09:46:48.550132 12320 process.cpp:991]
> libprocess is initialized on 172.30.2.124:39586 for 8 cpus
> [09:46:48]W: [Step 11/11] I0229 09:46:48.550712 12320 logging.cpp:193]
> Logging to STDERR
> [09:46:48]W: [Step 11/11] I0229 09:46:48.552098 12320 exec.cpp:143]
> Version: 0.28.0
> [09:46:48]W: [Step 11/11] I0229 09:46:48.557407 12370 exec.cpp:193]
> Executor started at: executor(1)@172.30.2.124:39586 with pid 12320
> [09:46:48]W: [Step 11/11] I0229 09:46:48.559065 1180 slave.cpp:2643] Got
> registration for executor 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 from executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] I0229 09:46:48.560705 12374 exec.cpp:217]
> Executor registered on slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> [09:46:48]W: [Step 11/11] I0229 09:46:48.560752 1180 slave.cpp:1863]
> Sending queued task 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' to executor
> 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 at executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] I0229 09:46:48.562134 12374 exec.cpp:229]
> Executor::registered took 256564ns
> [09:46:48]W: [Step 11/11] I0229 09:46:48.562368 12374 exec.cpp:304]
> Executor asked to run task 'cd81ece8-93b2-4e8a-a4b0-b566038bf281'
> [09:46:48]W: [Step 11/11] I0229 09:46:48.562463 12374 exec.cpp:313]
> Executor::launchTask took 75896ns
> [09:46:48] : [Step 11/11] Registered executor on
> ip-172-30-2-124.mesosphere.io
> [09:46:48] : [Step 11/11] Starting task cd81ece8-93b2-4e8a-a4b0-b566038bf281
> [09:46:48] : [Step 11/11] Forked command at 12377
> [09:46:48]W: [Step 11/11] I0229 09:46:48.566723 12369 exec.cpp:526]
> Executor sending status update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48] : [Step 11/11] sh -c 'ls -al /'
> [09:46:48]W: [Step 11/11] I0229 09:46:48.567494 1187 slave.cpp:3002]
> Handling status update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 from executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] Failed to exec: No such file or directory
> [09:46:48]W: [Step 11/11] I0229 09:46:48.568670 1186
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.568704 1186
> status_update_manager.cpp:497] Creating StatusUpdate stream for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569011 1186
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 to the slave
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569222 1183 slave.cpp:3400]
> Forwarding the update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 to [email protected]:37431
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569411 1183 slave.cpp:3294]
> Status update manager successfully handled status update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569447 1183 slave.cpp:3310]
> Sending acknowledgement for status update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 to executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569512 1187 master.cpp:4808]
> Status update TASK_RUNNING (UUID: 78b0b15b-22c8-479b-b2ee-bb02a7466964) for
> task cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 from slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at slave(422)@172.30.2.124:37431
> (ip-172-30-2-124.mesosphere.io)
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569546 1187 master.cpp:4856]
> Forwarding status update TASK_RUNNING (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569679 1187 master.cpp:6464]
> Updating the state of task cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569871 1184 sched.cpp:981]
> Scheduler::statusUpdate took 110230ns
> [09:46:48]W: [Step 11/11] I0229 09:46:48.569912 12374 exec.cpp:350]
> Executor received status update acknowledgement
> 78b0b15b-22c8-479b-b2ee-bb02a7466964 for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.570202 1184 master.cpp:3966]
> Processing ACKNOWLEDGE call 78b0b15b-22c8-479b-b2ee-bb02a7466964 for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (default) at
> [email protected]:37431 on slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> [09:46:48]W: [Step 11/11] I0229 09:46:48.570435 1186
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.570641 1183 slave.cpp:2412]
> Status update manager successfully handled status update acknowledgement
> (UUID: 78b0b15b-22c8-479b-b2ee-bb02a7466964) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.636754 1182
> hierarchical.cpp:1623] Filtered offer with cpus(*):1; mem(*):896;
> disk(*):1024; ports(*):[31000-32000] on slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 for framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.636795 1182
> hierarchical.cpp:1437] No resources available to allocate!
> [09:46:48]W: [Step 11/11] I0229 09:46:48.636827 1182
> hierarchical.cpp:1532] No inverse offers to send out!
> [09:46:48]W: [Step 11/11] I0229 09:46:48.636849 1182
> hierarchical.cpp:1130] Performed allocation for 1 slaves in 503523ns
> [09:46:48] : [Step 11/11] Command terminated with signal Aborted (pid:
> 12377)
> [09:46:48]W: [Step 11/11] I0229 09:46:48.665805 12369 exec.cpp:526]
> Executor sending status update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.666326 1184 slave.cpp:3002]
> Handling status update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 from executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] I0229 09:46:48.667079 1183 slave.cpp:5677]
> Terminating task cd81ece8-93b2-4e8a-a4b0-b566038bf281
> [09:46:48]W: [Step 11/11] I0229 09:46:48.667944 1180
> status_update_manager.cpp:320] Received status update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668077 1180
> status_update_manager.cpp:374] Forwarding update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 to the slave
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668303 1182 slave.cpp:3400]
> Forwarding the update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 to [email protected]:37431
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668453 1182 slave.cpp:3294]
> Status update manager successfully handled status update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668499 1182 slave.cpp:3310]
> Sending acknowledgement for status update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 to executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668642 1181 master.cpp:4808]
> Status update TASK_FAILED (UUID: 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for
> task cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 from slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at slave(422)@172.30.2.124:37431
> (ip-172-30-2-124.mesosphere.io)
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668689 1181 master.cpp:4856]
> Forwarding status update TASK_FAILED (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668826 1181 master.cpp:6464]
> Updating the state of task cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (latest state: TASK_FAILED, status
> update state: TASK_FAILED)
> [09:46:48]W: [Step 11/11] I0229 09:46:48.668920 12373 exec.cpp:350]
> Executor received status update acknowledgement
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669082 1183 sched.cpp:981]
> Scheduler::statusUpdate took 143562ns
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669242 1186 hierarchical.cpp:890]
> Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: ) on slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 from framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48] : [Step 11/11]
> ../../src/tests/containerizer/provisioner_docker_tests.cpp:379: Failure
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669381 1186 master.cpp:3966]
> Processing ACKNOWLEDGE call 265863c0-80d5-48a4-ac87-6f0de02ddbcb for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (default) at
> [email protected]:37431 on slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> [09:46:48] : [Step 11/11] Value of: statusFinished->state()
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669421 1166 sched.cpp:1903] Asked
> to stop the driver
> [09:46:48] : [Step 11/11] Actual: TASK_FAILED
> [09:46:48] : [Step 11/11] Expected: TASK_FINISHED
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669423 1186 master.cpp:6530]
> Removing task cd81ece8-93b2-4e8a-a4b0-b566038bf281 with resources cpus(*):1;
> mem(*):128 of framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 on slave
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0 at slave(422)@172.30.2.124:37431
> (ip-172-30-2-124.mesosphere.io)
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669519 1181 sched.cpp:1143]
> Stopping framework '3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000'
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669746 1186 master.cpp:5940]
> Processing TEARDOWN call for framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (default) at
> [email protected]:37431
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669778 1186 master.cpp:5952]
> Removing framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 (default) at
> [email protected]:37431
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669850 1184
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.669946 1187 hierarchical.cpp:375]
> Deactivated framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670032 1184
> status_update_manager.cpp:528] Cleaning up status update stream for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670030 1180 slave.cpp:2079] Asked
> to shut down framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 by
> [email protected]:37431
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670080 1180 slave.cpp:2104]
> Shutting down framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670140 1180 slave.cpp:4198]
> Shutting down executor 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 at executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670253 1186 master.cpp:1026]
> Master terminating
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670295 1187 hierarchical.cpp:326]
> Removed framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670384 1180 slave.cpp:2412]
> Status update manager successfully handled status update acknowledgement
> (UUID: 265863c0-80d5-48a4-ac87-6f0de02ddbcb) for task
> cd81ece8-93b2-4e8a-a4b0-b566038bf281 of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670434 1180 slave.cpp:5718]
> Completing task cd81ece8-93b2-4e8a-a4b0-b566038bf281
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670588 1187 hierarchical.cpp:505]
> Removed slave 3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670605 12375 exec.cpp:390]
> Executor asked to shutdown
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670717 12375 exec.cpp:405]
> Executor::shutdown took 12737ns
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670728 12369 exec.cpp:87]
> Scheduling shutdown of the executor in 5secs
> [09:46:48]W: [Step 11/11] I0229 09:46:48.670922 1183 slave.cpp:3528]
> [email protected]:37431 exited
> [09:46:48]W: [Step 11/11] W0229 09:46:48.670940 1183 slave.cpp:3531]
> Master disconnected! Waiting for a new master to be elected
> [09:46:48]W: [Step 11/11] I0229 09:46:48.675063 1186
> containerizer.cpp:1378] Destroying container
> '7f271a3f-bada-4dfb-a37f-f6c6d7aefd89'
> [09:46:48]W: [Step 11/11] I0229 09:46:48.677278 1182 cgroups.cpp:2427]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89
> [09:46:48]W: [Step 11/11] I0229 09:46:48.679386 1184 cgroups.cpp:1409]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89 after
> 2.066176ms
> [09:46:48]W: [Step 11/11] I0229 09:46:48.681586 1186 cgroups.cpp:2445]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89
> [09:46:48]W: [Step 11/11] I0229 09:46:48.683552 1186 cgroups.cpp:1438]
> Successfullly thawed cgroup
> /sys/fs/cgroup/freezer/mesos/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89 after
> 1.926144ms
> [09:46:48]W: [Step 11/11] I0229 09:46:48.696513 1186 slave.cpp:3528]
> executor(1)@172.30.2.124:39586 exited
> [09:46:48]W: [Step 11/11] I0229 09:46:48.708107 1181
> containerizer.cpp:1594] Executor for container
> '7f271a3f-bada-4dfb-a37f-f6c6d7aefd89' has exited
> [09:46:48]W: [Step 11/11] I0229 09:46:48.710535 1186 linux.cpp:765]
> Ignoring unmounting sandbox/work directory for container
> 7f271a3f-bada-4dfb-a37f-f6c6d7aefd89
> [09:46:48]W: [Step 11/11] I0229 09:46:48.710969 1187 provisioner.cpp:330]
> Destroying container rootfs at
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/provisioner/containers/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89/backends/copy/rootfses/6f8be9d5-12fe-4b66-9ff3-fda1efbb2519'
> for container 7f271a3f-bada-4dfb-a37f-f6c6d7aefd89
> [09:46:48]W: [Step 11/11] I0229 09:46:48.809336 1183 slave.cpp:3886]
> Executor 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 terminated with signal Killed
> [09:46:48]W: [Step 11/11] I0229 09:46:48.809378 1183 slave.cpp:3990]
> Cleaning up executor 'cd81ece8-93b2-4e8a-a4b0-b566038bf281' of framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000 at executor(1)@172.30.2.124:39586
> [09:46:48]W: [Step 11/11] I0229 09:46:48.809614 1187 gc.cpp:54] Scheduling
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/frameworks/3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000/executors/cd81ece8-93b2-4e8a-a4b0-b566038bf281/runs/7f271a3f-bada-4dfb-a37f-f6c6d7aefd89'
> for gc 6.9999906309837days in the future
> [09:46:48]W: [Step 11/11] I0229 09:46:48.809703 1183 slave.cpp:4078]
> Cleaning up framework 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.809739 1187 gc.cpp:54] Scheduling
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/frameworks/3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000/executors/cd81ece8-93b2-4e8a-a4b0-b566038bf281'
> for gc 6.99999062896889days in the future
> [09:46:48]W: [Step 11/11] I0229 09:46:48.809801 1182
> status_update_manager.cpp:282] Closing status update streams for framework
> 3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000
> [09:46:48]W: [Step 11/11] I0229 09:46:48.809854 1187 gc.cpp:54] Scheduling
> '/tmp/ProvisionerDockerRegistryPullerTest_ROOT_INTERNET_CURL_ShellCommand_5BWCfv/slaves/3fbb2fb0-4f18-498b-a440-9acbf6923a13-S0/frameworks/3fbb2fb0-4f18-498b-a440-9acbf6923a13-0000'
> for gc 6.99999062718519days in the future
> [09:46:48]W: [Step 11/11] I0229 09:46:48.810493 1187 slave.cpp:668] Slave
> terminating
> [09:46:48]W: [Step 11/11] Using temporary directory
> '/tmp/ContainerizerTest_ROOT_CGROUPS_BalloonFramework_e9Aoqv'
> [09:46:48] : [Step 11/11] [ FAILED ]
> ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand (2193 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
