[MESOS-5667] CniIsolatorTest.ROOT_INTERNET_CURL_LaunchCommandTask fails on CentOS 7. - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.0.0
Component/s: containerization, test
Labels:
Environment:

CenOS 7 with/without SSL

Epic Link:
CNI Support
Sprint:
Mesosphere Sprint 37
Story Points:
2

Description

[22:41:54] :	 [Step 10/10] [ RUN      ] CniIsolatorTest.ROOT_INTERNET_CURL_LaunchCommandTask
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.348641 30896 cluster.cpp:155] Creating default 'local' authorizer
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.353384 30896 leveldb.cpp:174] Opened db in 4.634552ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.354763 30896 leveldb.cpp:181] Compacted db in 1.360201ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.354784 30896 leveldb.cpp:196] Created db iterator in 3421ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.354790 30896 leveldb.cpp:202] Seeked to beginning of db in 633ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.354797 30896 leveldb.cpp:271] Iterated through 0 keys in the db in 401ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.354811 30896 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.354990 30913 recover.cpp:451] Starting replica recovery
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.355123 30915 recover.cpp:477] Replica is in EMPTY status
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.355391 30915 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (18695)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.355479 30912 recover.cpp:197] Received a recover response from a replica in EMPTY status
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.355581 30914 recover.cpp:568] Updating replica status to STARTING
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356091 30910 master.cpp:382] Master 27c796db-6f98-4d61-96c0-f583f22787ff (ip-172-30-2-105.mesosphere.io) started on 172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356104 30910 master.cpp:384] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/KhgYrQ/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/KhgYrQ/master" --zk_session_timeout="10secs"
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356237 30910 master.cpp:434] Master only allowing authenticated frameworks to register
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356245 30910 master.cpp:448] Master only allowing authenticated agents to register
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356247 30910 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356251 30910 credentials.hpp:37] Loading credentials for authentication from '/tmp/KhgYrQ/credentials'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356351 30910 master.cpp:506] Using default 'crammd5' authenticator
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356389 30910 master.cpp:578] Using default 'basic' HTTP authenticator
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356439 30910 master.cpp:658] Using default 'basic' HTTP framework authenticator
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356467 30910 master.cpp:705] Authorization enabled
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356531 30913 whitelist_watcher.cpp:77] No whitelist given
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356549 30912 hierarchical.cpp:142] Initialized hierarchical allocator process
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356868 30916 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.232816ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356884 30916 replica.cpp:320] Persisted replica status to STARTING
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.356945 30916 recover.cpp:477] Replica is in STARTING status
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.357100 30917 master.cpp:1969] The newly elected leader is master@172.30.2.105:40724 with id 27c796db-6f98-4d61-96c0-f583f22787ff
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.357115 30917 master.cpp:1982] Elected as the leading master!
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.357122 30917 master.cpp:1669] Recovering from registrar
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.357213 30910 registrar.cpp:332] Recovering registrar
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.357429 30913 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (18698)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.357549 30914 recover.cpp:197] Received a recover response from a replica in STARTING status
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.357728 30913 recover.cpp:568] Updating replica status to VOTING
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.358937 30913 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.14792ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.358952 30913 replica.cpp:320] Persisted replica status to VOTING
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.358986 30913 recover.cpp:582] Successfully joined the Paxos group
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.359041 30913 recover.cpp:466] Recover process terminated
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.359180 30916 log.cpp:553] Attempting to start the writer
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.359578 30917 replica.cpp:493] Replica received implicit promise request from (18699)@172.30.2.105:40724 with proposal 1
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.360752 30917 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.157449ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.360767 30917 replica.cpp:342] Persisted promised to 1
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.360982 30914 coordinator.cpp:238] Coordinator attempting to fill missing positions
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.361426 30910 replica.cpp:388] Replica received explicit promise request from (18700)@172.30.2.105:40724 for position 0 with proposal 2
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.362571 30910 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.124969ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.362587 30910 replica.cpp:712] Persisted action at 0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.362999 30911 replica.cpp:537] Replica received write request for position 0 from (18701)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.363030 30911 leveldb.cpp:436] Reading position from leveldb took 14967ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.364264 30911 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.214497ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.364279 30911 replica.cpp:712] Persisted action at 0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.364470 30910 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.365622 30910 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.131398ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.365636 30910 replica.cpp:712] Persisted action at 0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.365643 30910 replica.cpp:697] Replica learned NOP action at position 0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.365769 30915 log.cpp:569] Writer started with ending position 0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.366080 30913 leveldb.cpp:436] Reading position from leveldb took 8794ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.366284 30915 registrar.cpp:365] Successfully fetched the registry (0B) in 9.053952ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.366315 30915 registrar.cpp:464] Applied 1 operations in 3436ns; attempting to update the 'registry'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.366487 30911 log.cpp:577] Attempting to append 209 bytes to the log
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.366539 30917 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.366839 30917 replica.cpp:537] Replica received write request for position 1 from (18702)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.367966 30917 leveldb.cpp:341] Persisting action (228 bytes) to leveldb took 1.106053ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.367982 30917 replica.cpp:712] Persisted action at 1
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.368201 30915 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.371786 30915 leveldb.cpp:341] Persisting action (230 bytes) to leveldb took 3.566076ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.371803 30915 replica.cpp:712] Persisted action at 1
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.371809 30915 replica.cpp:697] Replica learned APPEND action at position 1
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.372032 30910 registrar.cpp:509] Successfully updated the 'registry' in 5.693952ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.372097 30910 registrar.cpp:395] Successfully recovered registrar
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.372107 30911 log.cpp:596] Attempting to truncate the log to 1
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.372151 30910 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.372218 30911 master.cpp:1777] Recovered 0 agents from the Registry (170B) ; allowing 10mins for agents to re-register
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.372242 30915 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.372467 30914 replica.cpp:537] Replica received write request for position 2 from (18703)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.373693 30914 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.207676ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.373708 30914 replica.cpp:712] Persisted action at 2
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.373920 30913 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.375115 30913 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.17978ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.375145 30913 leveldb.cpp:399] Deleting ~1 keys from leveldb took 14216ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.375154 30913 replica.cpp:712] Persisted action at 2
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.375159 30913 replica.cpp:697] Replica learned TRUNCATE action at position 2
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.383839 30896 containerizer.cpp:201] Using isolation: docker/runtime,filesystem/linux,network/cni
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.388789 30896 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
[22:41:54]W:	 [Step 10/10] E0619 22:41:54.393234 30896 shell.hpp:106] Command 'hadoop version 2>&1' failed; this is the output:
[22:41:54]W:	 [Step 10/10] sh: hadoop: command not found
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.393265 30896 fetcher.cpp:62] Skipping URI fetcher plugin 'hadoop' as it could not be created: 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
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.393316 30896 registry_puller.cpp:111] Creating registry puller with docker registry 'https://registry-1.docker.io'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.395668 30896 cluster.cpp:432] Creating default 'local' authorizer
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396100 30914 slave.cpp:203] Agent started on 469)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396116 30914 slave.cpp:204] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/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/KhgYrQ/store" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/http_credentials" --image_providers="docker" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="docker/runtime,filesystem/linux,network/cni" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --network_cni_config_dir="/tmp/KhgYrQ/configs" --network_cni_plugins_dir="/tmp/KhgYrQ/plugins" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI"
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396380 30914 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/credential'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396495 30914 slave.cpp:341] Agent using credential for: test-principal
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396509 30914 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/http_credentials'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396586 30914 slave.cpp:393] Using default 'basic' HTTP authenticator
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396698 30914 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
[22:41:54]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396780 30896 sched.cpp:224] Version: 1.0.0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.396991 30914 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397020 30914 slave.cpp:600] Agent attributes: [  ]
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397029 30914 slave.cpp:605] Agent hostname: ip-172-30-2-105.mesosphere.io
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397040 30916 sched.cpp:328] New master detected at master@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397068 30916 sched.cpp:394] Authenticating with master master@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397078 30916 sched.cpp:401] Using default CRAM-MD5 authenticatee
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397188 30916 authenticatee.cpp:121] Creating new client SASL connection
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397467 30914 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/meta'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397476 30912 master.cpp:5943] Authenticating scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397544 30913 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(953)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397614 30915 status_update_manager.cpp:200] Recovering status update manager
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397668 30912 authenticator.cpp:98] Creating new server SASL connection
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397709 30915 containerizer.cpp:514] Recovering containerizer
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397869 30912 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397886 30912 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397927 30912 authenticator.cpp:204] Received SASL authentication start
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.397964 30912 authenticator.cpp:326] Authentication requires more steps
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398000 30912 authenticatee.cpp:259] Received SASL authentication step
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398052 30912 authenticator.cpp:232] Received SASL authentication step
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398066 30912 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398073 30912 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398087 30912 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398098 30912 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398103 30912 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398108 30912 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398116 30912 authenticator.cpp:318] Authentication success
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398162 30914 authenticatee.cpp:299] Authentication success
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398181 30913 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(953)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398200 30912 master.cpp:5973] Successfully authenticated principal 'test-principal' at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398270 30914 sched.cpp:484] Successfully authenticated with master master@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398280 30914 sched.cpp:800] Sending SUBSCRIBE call to master@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398342 30914 sched.cpp:833] Will retry registration in 869.123866ms if necessary
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398381 30916 master.cpp:2539] Received SUBSCRIBE call for framework 'default' at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398398 30916 master.cpp:2008] Authorizing framework principal 'test-principal' to receive offers for role '*'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398483 30916 master.cpp:2615] Subscribing framework default with checkpointing disabled and capabilities [  ]
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398679 30916 sched.cpp:723] Framework registered with 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398701 30916 sched.cpp:737] Scheduler::registered took 10291ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398784 30910 hierarchical.cpp:264] Added framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398802 30910 hierarchical.cpp:1488] No allocations performed
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398808 30910 hierarchical.cpp:1583] No inverse offers to send out!
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.398818 30910 hierarchical.cpp:1139] Performed allocation for 0 agents in 22451ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399222 30916 metadata_manager.cpp:205] No images to load from disk. Docker provisioner image storage path '/tmp/KhgYrQ/store/storedImages' does not exist
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399318 30910 provisioner.cpp:253] Provisioner recovery complete
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399453 30913 slave.cpp:4845] Finished recovery
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399690 30913 slave.cpp:5017] Querying resource estimator for oversubscribable resources
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399796 30911 slave.cpp:967] New master detected at master@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399811 30911 slave.cpp:1029] Authenticating with master master@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399801 30914 status_update_manager.cpp:174] Pausing sending status updates
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399821 30911 slave.cpp:1040] Using default CRAM-MD5 authenticatee
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399855 30911 slave.cpp:1002] Detecting new master
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399879 30915 authenticatee.cpp:121] Creating new client SASL connection
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.399910 30911 slave.cpp:5031] Received oversubscribable resources  from the resource estimator
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400044 30915 master.cpp:5943] Authenticating slave(469)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400099 30910 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(954)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400151 30910 authenticator.cpp:98] Creating new server SASL connection
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400316 30910 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400329 30910 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400367 30910 authenticator.cpp:204] Received SASL authentication start
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400398 30910 authenticator.cpp:326] Authentication requires more steps
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400431 30910 authenticatee.cpp:259] Received SASL authentication step
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400516 30917 authenticator.cpp:232] Received SASL authentication step
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400530 30917 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400537 30917 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400544 30917 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400550 30917 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400554 30917 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400558 30917 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400566 30917 authenticator.cpp:318] Authentication success
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400609 30914 authenticatee.cpp:299] Authentication success
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400640 30912 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(954)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400682 30917 master.cpp:5973] Successfully authenticated principal 'test-principal' at slave(469)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400738 30911 slave.cpp:1108] Successfully authenticated with master master@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400790 30911 slave.cpp:1511] Will retry registration in 13.364855ms if necessary
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400848 30913 master.cpp:4653] Registering agent at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io) with id 27c796db-6f98-4d61-96c0-f583f22787ff-S0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.400950 30914 registrar.cpp:464] Applied 1 operations in 16921ns; attempting to update the 'registry'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.401154 30915 log.cpp:577] Attempting to append 395 bytes to the log
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.401213 30914 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.401515 30914 replica.cpp:537] Replica received write request for position 3 from (18725)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.402851 30914 leveldb.cpp:341] Persisting action (414 bytes) to leveldb took 1.317458ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.402866 30914 replica.cpp:712] Persisted action at 3
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.403101 30917 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404217 30917 leveldb.cpp:341] Persisting action (416 bytes) to leveldb took 1.100393ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404233 30917 replica.cpp:712] Persisted action at 3
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404239 30917 replica.cpp:697] Replica learned APPEND action at position 3
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404495 30915 registrar.cpp:509] Successfully updated the 'registry' in 3.521792ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404561 30913 log.cpp:596] Attempting to truncate the log to 3
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404621 30915 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404690 30910 master.cpp:4721] Registered agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404726 30915 slave.cpp:3747] Received ping from slave-observer(429)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404747 30916 hierarchical.cpp:473] Added agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 (ip-172-30-2-105.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404825 30915 slave.cpp:1152] Registered with master master@172.30.2.105:40724; given agent ID 27c796db-6f98-4d61-96c0-f583f22787ff-S0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404840 30915 fetcher.cpp:86] Clearing fetcher cache
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404880 30910 replica.cpp:537] Replica received write request for position 4 from (18726)@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404911 30916 hierarchical.cpp:1583] No inverse offers to send out!
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404932 30913 status_update_manager.cpp:181] Resuming sending status updates
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.404942 30916 hierarchical.cpp:1162] Performed allocation for agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 in 168147ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405025 30911 master.cpp:5772] Sending 1 offers to framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (default) at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405082 30915 slave.cpp:1175] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/meta/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/slave.info'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405177 30911 sched.cpp:897] Scheduler::resourceOffers took 55063ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405239 30915 slave.cpp:1212] Forwarding total oversubscribed resources 
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405299 30911 master.cpp:5066] Received update of agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io) with total oversubscribed resources 
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405318 30896 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128
[22:41:54]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405387 30911 hierarchical.cpp:531] Agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 (ip-172-30-2-105.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])
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405421 30911 hierarchical.cpp:1488] No allocations performed
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405431 30911 hierarchical.cpp:1583] No inverse offers to send out!
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405447 30911 hierarchical.cpp:1162] Performed allocation for agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 in 40224ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405643 30914 master.cpp:3457] Processing ACCEPT call for offers: [ 27c796db-6f98-4d61-96c0-f583f22787ff-O0 ] on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io) for framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (default) at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.405668 30914 master.cpp:3095] Authorizing framework principal 'test-principal' to launch task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406030 30912 master.hpp:177] Adding task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 with resources cpus(*):1; mem(*):128 on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 (ip-172-30-2-105.mesosphere.io)
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406056 30912 master.cpp:3946] Launching task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (default) at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724 with resources cpus(*):1; mem(*):128 on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io)
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406158 30916 slave.cpp:1551] Got assigned task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 for framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406193 30912 hierarchical.cpp:891] 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 agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 from framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406214 30912 hierarchical.cpp:928] Framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 filtered agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 for 5secs
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406250 30916 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[22:41:54]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406347 30910 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.44747ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406359 30910 replica.cpp:712] Persisted action at 4
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406381 30916 slave.cpp:1670] Launching task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 for framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406420 30916 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[22:41:54]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406555 30914 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.406793 30916 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000/executors/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2/runs/548370b5-05f2-4e33-8f6f-015aa3fd1af4' to user 'root'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.408360 30914 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.635458ms
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.408453 30914 leveldb.cpp:399] Deleting ~2 keys from leveldb took 53370ns
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.408469 30914 replica.cpp:712] Persisted action at 4
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.408480 30914 replica.cpp:697] Replica learned TRUNCATE action at position 4
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.411355 30916 slave.cpp:5734] Launching executor d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000/executors/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2/runs/548370b5-05f2-4e33-8f6f-015aa3fd1af4'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.411485 30916 slave.cpp:1896] Queuing task 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' for executor 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.411516 30915 containerizer.cpp:773] Starting container '548370b5-05f2-4e33-8f6f-015aa3fd1af4' for executor 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' of framework '27c796db-6f98-4d61-96c0-f583f22787ff-0000'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.411521 30916 slave.cpp:920] Successfully attached file '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000/executors/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2/runs/548370b5-05f2-4e33-8f6f-015aa3fd1af4'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.411733 30914 metadata_manager.cpp:167] Looking for image 'alpine'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.412009 30911 registry_puller.cpp:235] Pulling image 'library/alpine' from 'docker-manifest://registry-1.docker.io:443library/alpine?latest#https' to '/tmp/KhgYrQ/store/staging/0cVlJm'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.870712 30915 registry_puller.cpp:258] The manifest for image 'library/alpine' is '{
[22:41:54]W:	 [Step 10/10]    "schemaVersion": 1,
[22:41:54]W:	 [Step 10/10]    "name": "library/alpine",
[22:41:54]W:	 [Step 10/10]    "tag": "latest",
[22:41:54]W:	 [Step 10/10]    "architecture": "amd64",
[22:41:54]W:	 [Step 10/10]    "fsLayers": [
[22:41:54]W:	 [Step 10/10]       {
[22:41:54]W:	 [Step 10/10]          "blobSum": "sha256:fae91920dcd4542f97c9350b3157139a5d901362c2abec284de5ebd1b45b4957"
[22:41:54]W:	 [Step 10/10]       }
[22:41:54]W:	 [Step 10/10]    ],
[22:41:54]W:	 [Step 10/10]    "history": [
[22:41:54]W:	 [Step 10/10]       {
[22:41:54]W:	 [Step 10/10]          "v1Compatibility": "{\"architecture\":\"amd64\",\"config\":{\"Hostname\":\"571cde9b03ce\",\"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},\"container\":\"571cde9b03ce6f46b78b8e9c5089d03034863a4ab9f05d3e4997d0e5e80a2a6e\",\"container_config\":{\"Hostname\":\"571cde9b03ce\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":null,\"Cmd\":[\"/bin/sh\",\"-c\",\"#(nop) ADD file:701fd33a2f463fd4bd459779276897ef01dcf998dd47f6c8eae34fa5e0886046 in /\"],\"Image\":\"\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":null,\"Labels\":null},\"created\":\"2016-06-02T21:43:31.291506236Z\",\"docker_version\":\"1.9.1\",\"id\":\"e43bd3919b4ed702040fe5d0b19c9a0778ae7d61f169cf98112a842746168e6b\",\"os\":\"linux\"}"
[22:41:54]W:	 [Step 10/10]       }
[22:41:54]W:	 [Step 10/10]    ],
[22:41:54]W:	 [Step 10/10]    "signatures": [
[22:41:54]W:	 [Step 10/10]       {
[22:41:54]W:	 [Step 10/10]          "header": {
[22:41:54]W:	 [Step 10/10]             "jwk": {
[22:41:54]W:	 [Step 10/10]                "crv": "P-256",
[22:41:54]W:	 [Step 10/10]                "kid": "IZ4C:AKG6:LLBK:4Y62:6YWU:OI2G:K2EN:ZOJH:GHRY:5PKA:PFEE:WZWD",
[22:41:54]W:	 [Step 10/10]                "kty": "EC",
[22:41:54]W:	 [Step 10/10]                "x": "hU3h5pMhA0tgT3mF41BH5EbsLy9Tv3O-bla53S8-25g",
[22:41:54]W:	 [Step 10/10]                "y": "Y9sM4tXh_3KKKeEhikWEGgTUlQLYJxPWCXcs_bVP4Pc"
[22:41:54]W:	 [Step 10/10]             },
[22:41:54]W:	 [Step 10/10]             "alg": "ES256"
[22:41:54]W:	 [Step 10/10]          },
[22:41:54]W:	 [Step 10/10]          "signature": "8SZVGFKd_Ovz9FtfNMoLRWkwayOY9zaTq4bgPnKPuFPK-48nhDTMlkMz52Nqm2SHCk2xtYYkhzLtE6wUctrjqA",
[22:41:54]W:	 [Step 10/10]          "protected": "eyJmb3JtYXRMZW5ndGgiOjEzNTgsImZvcm1hdFRhaWwiOiJDbjAiLCJ0aW1lIjoiMjAxNi0wNi0xOVQyMjo0MTo1NFoifQ"
[22:41:54]W:	 [Step 10/10]       }
[22:41:54]W:	 [Step 10/10]    ]
[22:41:54]W:	 [Step 10/10] }'
[22:41:54]W:	 [Step 10/10] I0619 22:41:54.870767 30915 registry_puller.cpp:368] Fetching blob 'sha256:fae91920dcd4542f97c9350b3157139a5d901362c2abec284de5ebd1b45b4957' for layer 'e43bd3919b4ed702040fe5d0b19c9a0778ae7d61f169cf98112a842746168e6b' of image 'library/alpine'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.357898 30910 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 for framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.357965 30910 hierarchical.cpp:1488] No allocations performed
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.357980 30910 hierarchical.cpp:1583] No inverse offers to send out!
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.358002 30910 hierarchical.cpp:1139] Performed allocation for 1 agents in 238814ns
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.474309 30911 registry_puller.cpp:305] Extracting layer tar ball '/tmp/KhgYrQ/store/staging/0cVlJm/sha256:fae91920dcd4542f97c9350b3157139a5d901362c2abec284de5ebd1b45b4957 to rootfs '/tmp/KhgYrQ/store/staging/0cVlJm/e43bd3919b4ed702040fe5d0b19c9a0778ae7d61f169cf98112a842746168e6b/rootfs'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.575764 30910 metadata_manager.cpp:155] Successfully cached image 'alpine'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.576198 30911 provisioner.cpp:294] Provisioning image rootfs '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/provisioner/containers/548370b5-05f2-4e33-8f6f-015aa3fd1af4/backends/copy/rootfses/4f5eb0d5-118b-4129-972d-0a7e6a374f6f' for container 548370b5-05f2-4e33-8f6f-015aa3fd1af4
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.576556 30910 copy.cpp:128] Copying layer path '/tmp/KhgYrQ/store/layers/e43bd3919b4ed702040fe5d0b19c9a0778ae7d61f169cf98112a842746168e6b/rootfs' to rootfs '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/provisioner/containers/548370b5-05f2-4e33-8f6f-015aa3fd1af4/backends/copy/rootfses/4f5eb0d5-118b-4129-972d-0a7e6a374f6f'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.676825 30916 containerizer.cpp:1267] Launching 'mesos-containerizer' with flags '--command="{"arguments":["mesos-executor","--sandbox_directory=\/mnt\/mesos\/sandbox","--user=root","--rootfs=\/mnt\/teamcity\/temp\/buildTmp\/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI\/provisioner\/containers\/548370b5-05f2-4e33-8f6f-015aa3fd1af4\/backends\/copy\/rootfses\/4f5eb0d5-118b-4129-972d-0a7e6a374f6f"],"shell":false,"user":"root","value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}" --commands="{"commands":[{"shell":true,"value":"#!\/bin\/sh\nset -x -e\n\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-containerizer mount --help=\"false\" --operation=\"make-rslave\" --path=\"\/\"\nmount -n --rbind '\/mnt\/teamcity\/temp\/buildTmp\/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI\/slaves\/27c796db-6f98-4d61-96c0-f583f22787ff-S0\/frameworks\/27c796db-6f98-4d61-96c0-f583f22787ff-0000\/executors\/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2\/runs\/548370b5-05f2-4e33-8f6f-015aa3fd1af4' '\/mnt\/teamcity\/temp\/buildTmp\/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI\/provisioner\/containers\/548370b5-05f2-4e33-8f6f-015aa3fd1af4\/backends\/copy\/rootfses\/4f5eb0d5-118b-4129-972d-0a7e6a374f6f\/mnt\/mesos\/sandbox'\n"}]}" --help="false" --pipe_read="17" --pipe_write="20" --sandbox="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000/executors/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2/runs/548370b5-05f2-4e33-8f6f-015aa3fd1af4" --user="root"'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.676923 30916 linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWUTS | CLONE_NEWNS
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.681491 30913 cni.cpp:683] Bind mounted '/proc/13484/ns/net' to '/run/mesos/isolators/network/cni/548370b5-05f2-4e33-8f6f-015aa3fd1af4/ns' for container 548370b5-05f2-4e33-8f6f-015aa3fd1af4
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.681712 30913 cni.cpp:977] Invoking CNI plugin 'mockPlugin' with network configuration '{"args":{"org.apache.mesos":{"network_info":{"name":"__MESOS_TEST__"}}},"name":"__MESOS_TEST__","type":"mockPlugin"}'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.776078 30916 cni.cpp:1066] Got assigned IPv4 address '172.17.0.1/16' from CNI network '__MESOS_TEST__' for container 548370b5-05f2-4e33-8f6f-015aa3fd1af4
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.776463 30913 cni.cpp:808] DNS nameservers for container 548370b5-05f2-4e33-8f6f-015aa3fd1af4 are:
[22:41:55]W:	 [Step 10/10] nameserver 172.30.0.2
[22:41:55]W:	 [Step 10/10] + /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer mount --help=false --operation=make-rslave --path=/
[22:41:55]W:	 [Step 10/10] + mount -n --rbind /mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000/executors/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2/runs/548370b5-05f2-4e33-8f6f-015aa3fd1af4 /mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/provisioner/containers/548370b5-05f2-4e33-8f6f-015aa3fd1af4/backends/copy/rootfses/4f5eb0d5-118b-4129-972d-0a7e6a374f6f/mnt/mesos/sandbox
[22:41:55]W:	 [Step 10/10] WARNING: Logging before InitGoogleLogging() is written to STDERR
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.944355 13484 process.cpp:1060] libprocess is initialized on 172.17.0.1:60396 with 8 worker threads
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.946605 13484 logging.cpp:199] Logging to STDERR
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.947335 13484 exec.cpp:161] Version: 1.0.0
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.947404 13541 exec.cpp:211] Executor started at: executor(1)@172.17.0.1:60396 with pid 13484
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.947883 30917 slave.cpp:2884] Got registration for executor 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 from executor(1)@172.17.0.1:60396
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.948427 13543 exec.cpp:236] Executor registered on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.948524 30914 slave.cpp:2061] Sending queued task 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' to executor 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 at executor(1)@172.17.0.1:60396
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.949061 13543 exec.cpp:248] Executor::registered took 75489ns
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.949213 13543 exec.cpp:323] Executor asked to run task 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.949246 13543 exec.cpp:332] Executor::launchTask took 21245ns
[22:41:55] :	 [Step 10/10] Received SUBSCRIBED event
[22:41:55] :	 [Step 10/10] Subscribed executor on ip-172-30-2-105.mesosphere.io
[22:41:55] :	 [Step 10/10] Received LAUNCH event
[22:41:55] :	 [Step 10/10] Starting task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2
[22:41:55] :	 [Step 10/10] Forked command at 13550
[22:41:55] :	 [Step 10/10] sh -c 'ifconfig'
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.953589 13547 exec.cpp:546] Executor sending status update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] Failed to exec: No such file or directory
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.953891 30917 slave.cpp:3267] Handling status update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 from executor(1)@172.17.0.1:60396
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954368 30910 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954385 30910 status_update_manager.cpp:497] Creating StatusUpdate stream for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954545 30910 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 to the agent
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954637 30911 slave.cpp:3665] Forwarding the update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 to master@172.30.2.105:40724
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954711 30911 slave.cpp:3559] Status update manager successfully handled status update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954732 30911 slave.cpp:3575] Sending acknowledgement for status update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 to executor(1)@172.17.0.1:60396
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954761 30914 master.cpp:5211] Status update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 from agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io)
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954788 30914 master.cpp:5259] Forwarding status update TASK_RUNNING (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954843 30914 master.cpp:6871] Updating the state of task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954934 13548 exec.cpp:369] Executor received status update acknowledgement 5caccf6c-9e1e-44cc-93d4-6851987802cd for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.954967 30910 sched.cpp:1005] Scheduler::statusUpdate took 57021ns
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.955070 30914 master.cpp:4365] Processing ACKNOWLEDGE call 5caccf6c-9e1e-44cc-93d4-6851987802cd for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (default) at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724 on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.955150 30911 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:55]W:	 [Step 10/10] I0619 22:41:55.955219 30911 slave.cpp:2653] Status update manager successfully handled status update acknowledgement (UUID: 5caccf6c-9e1e-44cc-93d4-6851987802cd) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56] :	 [Step 10/10] Command terminated with signal Aborted (pid: 13550)
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.054153 13541 exec.cpp:546] Executor sending status update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.054498 30913 slave.cpp:3267] Handling status update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 from executor(1)@172.17.0.1:60396
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.054955 30917 slave.cpp:6074] Terminating task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055366 30912 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055409 30912 status_update_manager.cpp:374] Forwarding update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 to the agent
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055485 30916 slave.cpp:3665] Forwarding the update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 to master@172.30.2.105:40724
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055558 30916 slave.cpp:3559] Status update manager successfully handled status update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56] :	 [Step 10/10] ../../src/tests/containerizer/cni_isolator_tests.cpp:216: Failure
[22:41:56] :	 [Step 10/10] Value of: statusFinished->state()
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055572 30916 slave.cpp:3575] Sending acknowledgement for status update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 to executor(1)@172.17.0.1:60396
[22:41:56] :	 [Step 10/10]   Actual: TASK_FAILED
[22:41:56] :	 [Step 10/10] Expected: TASK_FINISHED
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055613 30914 master.cpp:5211] Status update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 from agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io)
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055640 30914 master.cpp:5259] Forwarding status update TASK_FAILED (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055696 30914 master.cpp:6871] Updating the state of task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (latest state: TASK_FAILED, status update state: TASK_FAILED)
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055773 30912 sched.cpp:1005] Scheduler::statusUpdate took 29145ns
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055780 13546 exec.cpp:369] Executor received status update acknowledgement 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34 for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055816 30916 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 from framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055887 30911 master.cpp:4365] Processing ACKNOWLEDGE call 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34 for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (default) at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724 on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055907 30911 master.cpp:6937] Removing task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 with resources cpus(*):1; mem(*):128 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 on agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io)
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.055971 30896 sched.cpp:1964] Asked to stop the driver
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056030 30913 sched.cpp:1167] Stopping framework '27c796db-6f98-4d61-96c0-f583f22787ff-0000'
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056040 30916 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056073 30916 status_update_manager.cpp:528] Cleaning up status update stream for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056151 30915 master.cpp:6342] Processing TEARDOWN call for framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (default) at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056172 30915 master.cpp:6354] Removing framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 (default) at scheduler-af10d6a3-1ebc-4377-b44d-8c0dfbffcb8e@172.30.2.105:40724
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056197 30916 slave.cpp:2653] Status update manager successfully handled status update acknowledgement (UUID: 3d3632b6-f69b-4ca1-8bac-0b4e8e471d34) for task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2 of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056216 30916 slave.cpp:6115] Completing task d7416b1b-cd1c-422a-bbaa-bb28913eeaf2
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056218 30913 hierarchical.cpp:375] Deactivated framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056248 30916 slave.cpp:2274] Asked to shut down framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 by master@172.30.2.105:40724
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056265 30916 slave.cpp:2299] Shutting down framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056277 30916 slave.cpp:4470] Shutting down executor 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 at executor(1)@172.17.0.1:60396
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056468 30914 hierarchical.cpp:326] Removed framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.056634 30911 containerizer.cpp:1576] Destroying container '548370b5-05f2-4e33-8f6f-015aa3fd1af4'
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.057258 13543 exec.cpp:410] Executor asked to shutdown
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.057303 13543 exec.cpp:425] Executor::shutdown took 6363ns
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.057324 13547 exec.cpp:92] Scheduling shutdown of the executor in 5secs
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.058279 30910 cgroups.cpp:2676] Freezing cgroup /sys/fs/cgroup/freezer/mesos/548370b5-05f2-4e33-8f6f-015aa3fd1af4
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.059762 30912 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/548370b5-05f2-4e33-8f6f-015aa3fd1af4 after 1.460736ms
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.061364 30910 cgroups.cpp:2694] Thawing cgroup /sys/fs/cgroup/freezer/mesos/548370b5-05f2-4e33-8f6f-015aa3fd1af4
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.062861 30915 cgroups.cpp:1438] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/548370b5-05f2-4e33-8f6f-015aa3fd1af4 after 1.478912ms
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.064016 30910 slave.cpp:3793] executor(1)@172.17.0.1:60396 exited
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.078352 30915 containerizer.cpp:1812] Executor for container '548370b5-05f2-4e33-8f6f-015aa3fd1af4' has exited
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.179833 30916 cni.cpp:1217] Unmounted the network namespace handle '/run/mesos/isolators/network/cni/548370b5-05f2-4e33-8f6f-015aa3fd1af4/ns' for container 548370b5-05f2-4e33-8f6f-015aa3fd1af4
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.179924 30916 cni.cpp:1228] Removed the container directory '/run/mesos/isolators/network/cni/548370b5-05f2-4e33-8f6f-015aa3fd1af4'
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.180981 30913 provisioner.cpp:434] Destroying container rootfs at '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/provisioner/containers/548370b5-05f2-4e33-8f6f-015aa3fd1af4/backends/copy/rootfses/4f5eb0d5-118b-4129-972d-0a7e6a374f6f' for container 548370b5-05f2-4e33-8f6f-015aa3fd1af4
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280364 30912 slave.cpp:4152] Executor 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 terminated with signal Killed
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280406 30912 slave.cpp:4256] Cleaning up executor 'd7416b1b-cd1c-422a-bbaa-bb28913eeaf2' of framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000 at executor(1)@172.17.0.1:60396
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280545 30915 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000/executors/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2/runs/548370b5-05f2-4e33-8f6f-015aa3fd1af4' for gc 6.99999675365926days in the future
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280575 30912 slave.cpp:4344] Cleaning up framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280647 30915 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000/executors/d7416b1b-cd1c-422a-bbaa-bb28913eeaf2' for gc 6.99999675293037days in the future
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280654 30914 status_update_manager.cpp:282] Closing status update streams for framework 27c796db-6f98-4d61-96c0-f583f22787ff-0000
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280710 30915 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_GcX6XI/slaves/27c796db-6f98-4d61-96c0-f583f22787ff-S0/frameworks/27c796db-6f98-4d61-96c0-f583f22787ff-0000' for gc 6.99999675200296days in the future
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280745 30915 slave.cpp:839] Agent terminating
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280810 30912 master.cpp:1367] Agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io) disconnected
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280827 30912 master.cpp:2899] Disconnecting agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io)
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280844 30912 master.cpp:2918] Deactivating agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 at slave(469)@172.30.2.105:40724 (ip-172-30-2-105.mesosphere.io)
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.280912 30912 hierarchical.cpp:560] Agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0 deactivated
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.283011 30896 master.cpp:1214] Master terminating
[22:41:56]W:	 [Step 10/10] I0619 22:41:56.283140 30916 hierarchical.cpp:505] Removed agent 27c796db-6f98-4d61-96c0-f583f22787ff-S0
[22:41:56] :	 [Step 10/10] [  FAILED  ] CniIsolatorTest.ROOT_INTERNET_CURL_LaunchCommandTask (1945 ms)

Attachments

Activity

People

Assignee:: Gilbert Song

Reporter:: Gilbert Song

Shepherd:: Jie Yu

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 21/Jun/16 01:03

Updated:: 26/Apr/17 17:00

Resolved:: 22/Jun/16 23:05