mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bernd Mathiske (JIRA)" <j...@apache.org>
Subject [jira] [Created] (MESOS-4810) ProvisionerDockerRegistryPullerTest.ROOT_INTERNET_CURL_ShellCommand fails.
Date Mon, 29 Feb 2016 10:43:18 GMT
Bernd Mathiske created MESOS-4810:
-------------------------------------

             Summary: 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


{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 master@172.30.2.124: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 master@172.30.2.124:37431
[09:46:46]W:	 [Step 11/11] I0229 09:46:46.690146  1186 sched.cpp:382] Authenticating with master master@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 master@172.30.2.124:37431
[09:46:46]W:	 [Step 11/11] I0229 09:46:46.692325  1184 sched.cpp:776] Sending SUBSCRIBE call to master@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 master@172.30.2.124: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 master@172.30.2.124: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 master@172.30.2.124: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 master@172.30.2.124: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 master@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 master@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 master@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 scheduler-52603476-875a-49a8-85d4-c98d102cdfab@172.30.2.124: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 master@172.30.2.124: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] master@172.30.2.124: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)

Mime
View raw message