[MESOS-5669] CNI isolator should not return failure if /etc/hostname does not exist on host. - 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:

CentOS 6 with/without SSL

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

Description

/etc/hostname may not necessarily exist on every system (e.g., CentOS 6). Currently CNI isolator just return a failure if it does not exist on host, because the isolator need to mount it into the container. This is fine for /etc/host and /etc/resolv.conf, but we should make an exception for /etc/hostname, because hostname may still be accessible even if /etc/hostname doesn't exist.

This issue relates to 3 failure tests:

[22:45:21] :	 [Step 10/10] [ RUN      ] CniIsolatorTest.ROOT_INTERNET_CURL_LaunchCommandTask
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.647611 24647 cluster.cpp:155] Creating default 'local' authorizer
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.655230 24647 leveldb.cpp:174] Opened db in 7.510408ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.657680 24647 leveldb.cpp:181] Compacted db in 2.427309ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.657702 24647 leveldb.cpp:196] Created db iterator in 6209ns
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.657709 24647 leveldb.cpp:202] Seeked to beginning of db in 692ns
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.657713 24647 leveldb.cpp:271] Iterated through 0 keys in the db in 431ns
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.657727 24647 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.657888 24662 recover.cpp:451] Starting replica recovery
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.658051 24668 recover.cpp:477] Replica is in EMPTY status
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.658495 24664 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (18401)@172.30.2.247:42024
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.658583 24662 recover.cpp:197] Received a recover response from a replica in EMPTY status
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.658687 24664 recover.cpp:568] Updating replica status to STARTING
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659111 24664 master.cpp:382] Master 9a4a353b-91c5-43b9-8c37-19245c37758c (ip-172-30-2-247.mesosphere.io) started on 172.30.2.247:42024
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659126 24664 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/l8346Z/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/l8346Z/master" --zk_session_timeout="10secs"
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659267 24664 master.cpp:434] Master only allowing authenticated frameworks to register
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659276 24664 master.cpp:448] Master only allowing authenticated agents to register
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659278 24664 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659282 24664 credentials.hpp:37] Loading credentials for authentication from '/tmp/l8346Z/credentials'
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659375 24664 master.cpp:506] Using default 'crammd5' authenticator
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659415 24664 master.cpp:578] Using default 'basic' HTTP authenticator
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659495 24664 master.cpp:658] Using default 'basic' HTTP framework authenticator
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659569 24664 master.cpp:705] Authorization enabled
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659684 24666 hierarchical.cpp:142] Initialized hierarchical allocator process
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.659696 24665 whitelist_watcher.cpp:77] No whitelist given
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.660269 24666 master.cpp:1969] The newly elected leader is master@172.30.2.247:42024 with id 9a4a353b-91c5-43b9-8c37-19245c37758c
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.660281 24666 master.cpp:1982] Elected as the leading master!
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.660290 24666 master.cpp:1669] Recovering from registrar
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.660342 24662 registrar.cpp:332] Recovering registrar
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.661232 24669 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 2.48585ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.661254 24669 replica.cpp:320] Persisted replica status to STARTING
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.661326 24669 recover.cpp:477] Replica is in STARTING status
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.661667 24668 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (18404)@172.30.2.247:42024
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.661758 24665 recover.cpp:197] Received a recover response from a replica in STARTING status
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.661893 24664 recover.cpp:568] Updating replica status to VOTING
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.663851 24664 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.915617ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.663866 24664 replica.cpp:320] Persisted replica status to VOTING
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.663899 24664 recover.cpp:582] Successfully joined the Paxos group
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.663944 24664 recover.cpp:466] Recover process terminated
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.664088 24668 log.cpp:553] Attempting to start the writer
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.664556 24668 replica.cpp:493] Replica received implicit promise request from (18405)@172.30.2.247:42024 with proposal 1
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.666551 24668 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.971938ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.666566 24668 replica.cpp:342] Persisted promised to 1
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.666767 24667 coordinator.cpp:238] Coordinator attempting to fill missing positions
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.667230 24668 replica.cpp:388] Replica received explicit promise request from (18406)@172.30.2.247:42024 for position 0 with proposal 2
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.669271 24668 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 2.02399ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.669287 24668 replica.cpp:712] Persisted action at 0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.669656 24669 replica.cpp:537] Replica received write request for position 0 from (18407)@172.30.2.247:42024
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.669680 24669 leveldb.cpp:436] Reading position from leveldb took 10808ns
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.671674 24669 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.977316ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.671689 24669 replica.cpp:712] Persisted action at 0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.671907 24665 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.673920 24665 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.991274ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.673935 24665 replica.cpp:712] Persisted action at 0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.673941 24665 replica.cpp:697] Replica learned NOP action at position 0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.674190 24665 log.cpp:569] Writer started with ending position 0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.674489 24663 leveldb.cpp:436] Reading position from leveldb took 9059ns
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.674718 24663 registrar.cpp:365] Successfully fetched the registry (0B) in 14.355968ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.674747 24663 registrar.cpp:464] Applied 1 operations in 3070ns; attempting to update the 'registry'
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.674935 24665 log.cpp:577] Attempting to append 209 bytes to the log
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.674978 24665 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.675242 24666 replica.cpp:537] Replica received write request for position 1 from (18408)@172.30.2.247:42024
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.677088 24666 leveldb.cpp:341] Persisting action (228 bytes) to leveldb took 1.823904ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.677103 24666 replica.cpp:712] Persisted action at 1
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.677299 24667 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679270 24667 leveldb.cpp:341] Persisting action (230 bytes) to leveldb took 1.952303ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679286 24667 replica.cpp:712] Persisted action at 1
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679291 24667 replica.cpp:697] Replica learned APPEND action at position 1
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679481 24663 registrar.cpp:509] Successfully updated the 'registry' in 4.715264ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679503 24666 log.cpp:596] Attempting to truncate the log to 1
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679560 24667 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679581 24663 registrar.cpp:395] Successfully recovered registrar
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679745 24664 master.cpp:1777] Recovered 0 agents from the Registry (170B) ; allowing 10mins for agents to re-register
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679774 24662 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.679986 24662 replica.cpp:537] Replica received write request for position 2 from (18409)@172.30.2.247:42024
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.681895 24662 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.891877ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.681910 24662 replica.cpp:712] Persisted action at 2
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.682160 24666 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.684331 24666 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 2.153217ms
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.684375 24666 leveldb.cpp:399] Deleting ~1 keys from leveldb took 26973ns
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.684383 24666 replica.cpp:712] Persisted action at 2
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.684389 24666 replica.cpp:697] Replica learned TRUNCATE action at position 2
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.691529 24647 containerizer.cpp:201] Using isolation: docker/runtime,filesystem/linux,network/cni
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.694491 24647 linux_launcher.cpp:101] Using /cgroup/freezer as the freezer hierarchy for the Linux launcher
[22:45:21]W:	 [Step 10/10] E0619 22:45:21.699741 24647 shell.hpp:106] Command 'hadoop version 2>&1' failed; this is the output:
[22:45:21]W:	 [Step 10/10] sh: hadoop: command not found
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.699769 24647 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:45:21]W:	 [Step 10/10] I0619 22:45:21.699823 24647 registry_puller.cpp:111] Creating registry puller with docker registry 'https://registry-1.docker.io'
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.700865 24647 linux.cpp:146] Bind mounting '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_CVAWpG' and making it a shared mount
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.707801 24647 cni.cpp:286] Bind mounting '/var/run/mesos/isolators/network/cni' and making it a shared mount
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.714337 24647 cluster.cpp:432] Creating default 'local' authorizer
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.714825 24668 slave.cpp:203] Agent started on 468)@172.30.2.247:42024
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.714839 24668 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_CVAWpG/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/l8346Z/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_CVAWpG/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_CVAWpG/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/l8346Z/configs" --network_cni_plugins_dir="/tmp/l8346Z/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_CVAWpG"
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.715116 24668 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_CVAWpG/credential'
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.715195 24668 slave.cpp:341] Agent using credential for: test-principal
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.715214 24668 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_INTERNET_CURL_LaunchCommandTask_CVAWpG/http_credentials'
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.715296 24668 slave.cpp:393] Using default 'basic' HTTP authenticator
[22:45:21]W:	 [Step 10/10] I0619 22:45:21.715400 24668 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]

[22:45:38] :	 [Step 10/10] [ RUN      ] CniIsolatorTest.ROOT_VerifyCheckpointedInfo
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.459836 24647 cluster.cpp:155] Creating default 'local' authorizer
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.470319 24647 leveldb.cpp:174] Opened db in 10.34226ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.472771 24647 leveldb.cpp:181] Compacted db in 2.403554ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.472795 24647 leveldb.cpp:196] Created db iterator in 4446ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.472801 24647 leveldb.cpp:202] Seeked to beginning of db in 810ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.472806 24647 leveldb.cpp:271] Iterated through 0 keys in the db in 393ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.472822 24647 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.473093 24665 recover.cpp:451] Starting replica recovery
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.473260 24663 recover.cpp:477] Replica is in EMPTY status
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.473647 24663 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (18464)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.473752 24665 recover.cpp:197] Received a recover response from a replica in EMPTY status
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.473896 24667 recover.cpp:568] Updating replica status to STARTING
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474319 24663 master.cpp:382] Master 64f1f7ac-e810-4fb1-b549-6e29fc62622b (ip-172-30-2-247.mesosphere.io) started on 172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474329 24663 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/qJWqSY/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/qJWqSY/master" --zk_session_timeout="10secs"
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474452 24663 master.cpp:434] Master only allowing authenticated frameworks to register
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474457 24663 master.cpp:448] Master only allowing authenticated agents to register
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474459 24663 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474463 24663 credentials.hpp:37] Loading credentials for authentication from '/tmp/qJWqSY/credentials'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474551 24663 master.cpp:506] Using default 'crammd5' authenticator
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474598 24663 master.cpp:578] Using default 'basic' HTTP authenticator
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474643 24663 master.cpp:658] Using default 'basic' HTTP framework authenticator
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474674 24663 master.cpp:705] Authorization enabled
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474771 24668 whitelist_watcher.cpp:77] No whitelist given
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.474798 24664 hierarchical.cpp:142] Initialized hierarchical allocator process
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.475177 24663 master.cpp:1969] The newly elected leader is master@172.30.2.247:42024 with id 64f1f7ac-e810-4fb1-b549-6e29fc62622b
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.475188 24663 master.cpp:1982] Elected as the leading master!
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.475191 24663 master.cpp:1669] Recovering from registrar
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.475244 24662 registrar.cpp:332] Recovering registrar
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.476292 24669 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 2.312046ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.476308 24669 replica.cpp:320] Persisted replica status to STARTING
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.476368 24669 recover.cpp:477] Replica is in STARTING status
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.476687 24668 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (18467)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.476824 24666 recover.cpp:197] Received a recover response from a replica in STARTING status
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.476953 24668 recover.cpp:568] Updating replica status to VOTING
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.478798 24668 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.793996ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.478813 24668 replica.cpp:320] Persisted replica status to VOTING
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.478844 24668 recover.cpp:582] Successfully joined the Paxos group
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.478889 24668 recover.cpp:466] Recover process terminated
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.479060 24665 log.cpp:553] Attempting to start the writer
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.479547 24667 replica.cpp:493] Replica received implicit promise request from (18468)@172.30.2.247:42024 with proposal 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.481433 24667 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.8684ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.481449 24667 replica.cpp:342] Persisted promised to 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.481667 24662 coordinator.cpp:238] Coordinator attempting to fill missing positions
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.482067 24668 replica.cpp:388] Replica received explicit promise request from (18469)@172.30.2.247:42024 for position 0 with proposal 2
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.483842 24668 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.754044ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.483858 24668 replica.cpp:712] Persisted action at 0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.484235 24665 replica.cpp:537] Replica received write request for position 0 from (18470)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.484261 24665 leveldb.cpp:436] Reading position from leveldb took 10298ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.486331 24665 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 2.057217ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.486346 24665 replica.cpp:712] Persisted action at 0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.486574 24669 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.488533 24669 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.941228ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.488548 24669 replica.cpp:712] Persisted action at 0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.488553 24669 replica.cpp:697] Replica learned NOP action at position 0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.488690 24666 log.cpp:569] Writer started with ending position 0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.489006 24662 leveldb.cpp:436] Reading position from leveldb took 11082ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.489244 24667 registrar.cpp:365] Successfully fetched the registry (0B) in 13.976832ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.489276 24667 registrar.cpp:464] Applied 1 operations in 3438ns; attempting to update the 'registry'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.489450 24662 log.cpp:577] Attempting to append 209 bytes to the log
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.489514 24665 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.489785 24662 replica.cpp:537] Replica received write request for position 1 from (18471)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.491642 24662 leveldb.cpp:341] Persisting action (228 bytes) to leveldb took 1.838371ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.491657 24662 replica.cpp:712] Persisted action at 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.491885 24665 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.493649 24665 leveldb.cpp:341] Persisting action (230 bytes) to leveldb took 1.743495ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.493665 24665 replica.cpp:712] Persisted action at 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.493670 24665 replica.cpp:697] Replica learned APPEND action at position 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.493930 24669 registrar.cpp:509] Successfully updated the 'registry' in 4.638976ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.493983 24667 log.cpp:596] Attempting to truncate the log to 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.493994 24669 registrar.cpp:395] Successfully recovered registrar
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.494034 24668 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.494197 24662 master.cpp:1777] Recovered 0 agents from the Registry (170B) ; allowing 10mins for agents to re-register
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.494210 24666 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.494396 24662 replica.cpp:537] Replica received write request for position 2 from (18472)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.496301 24662 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.884992ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.496315 24662 replica.cpp:712] Persisted action at 2
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.496574 24666 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.498500 24666 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.906093ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.498529 24666 leveldb.cpp:399] Deleting ~1 keys from leveldb took 13787ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.498538 24666 replica.cpp:712] Persisted action at 2
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.498543 24666 replica.cpp:697] Replica learned TRUNCATE action at position 2
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.505269 24647 containerizer.cpp:201] Using isolation: network/cni,filesystem/posix
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.508313 24647 linux_launcher.cpp:101] Using /cgroup/freezer as the freezer hierarchy for the Linux launcher
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.509832 24647 cluster.cpp:432] Creating default 'local' authorizer
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510205 24666 slave.cpp:203] Agent started on 469)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510213 24666 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_VerifyCheckpointedInfo_IIWOru/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/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_VerifyCheckpointedInfo_IIWOru/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="network/cni" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --network_cni_config_dir="/tmp/qJWqSY/configs" --network_cni_plugins_dir="/tmp/qJWqSY/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_VerifyCheckpointedInfo_IIWOru"
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510442 24666 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/credential'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510510 24666 slave.cpp:341] Agent using credential for: test-principal
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510521 24666 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/http_credentials'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510604 24666 slave.cpp:393] Using default 'basic' HTTP authenticator
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510696 24666 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
[22:45:38]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510915 24647 sched.cpp:224] Version: 1.0.0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510962 24666 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510984 24666 slave.cpp:600] Agent attributes: [  ]
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.510989 24666 slave.cpp:605] Agent hostname: ip-172-30-2-247.mesosphere.io
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511077 24669 sched.cpp:328] New master detected at master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511162 24669 sched.cpp:394] Authenticating with master master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511173 24669 sched.cpp:401] Using default CRAM-MD5 authenticatee
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511294 24662 authenticatee.cpp:121] Creating new client SASL connection
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511371 24667 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/meta'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511494 24665 master.cpp:5943] Authenticating scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511523 24668 status_update_manager.cpp:200] Recovering status update manager
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511566 24662 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(957)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511612 24664 containerizer.cpp:514] Recovering containerizer
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511706 24667 authenticator.cpp:98] Creating new server SASL connection
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511800 24667 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511816 24667 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511865 24667 authenticator.cpp:204] Received SASL authentication start
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511934 24667 authenticator.cpp:326] Authentication requires more steps
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.511977 24667 authenticatee.cpp:259] Received SASL authentication step
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512080 24668 authenticator.cpp:232] Received SASL authentication step
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512102 24668 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512112 24668 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512125 24668 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512136 24668 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512145 24668 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512152 24668 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512166 24668 authenticator.cpp:318] Authentication success
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512228 24665 authenticatee.cpp:299] Authentication success
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512233 24668 master.cpp:5973] Successfully authenticated principal 'test-principal' at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512253 24667 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(957)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512434 24664 sched.cpp:484] Successfully authenticated with master master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512445 24664 sched.cpp:800] Sending SUBSCRIBE call to master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512490 24667 provisioner.cpp:253] Provisioner recovery complete
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512609 24664 sched.cpp:833] Will retry registration in 550.501359ms if necessary
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512648 24663 master.cpp:2539] Received SUBSCRIBE call for framework 'default' at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512665 24663 master.cpp:2008] Authorizing framework principal 'test-principal' to receive offers for role '*'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512678 24667 slave.cpp:4845] Finished recovery
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512763 24663 master.cpp:2615] Subscribing framework default with checkpointing disabled and capabilities [  ]
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512876 24664 hierarchical.cpp:264] Added framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512893 24664 hierarchical.cpp:1488] No allocations performed
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512905 24664 hierarchical.cpp:1583] No inverse offers to send out!
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512922 24664 hierarchical.cpp:1139] Performed allocation for 0 agents in 33065ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.512940 24667 slave.cpp:5017] Querying resource estimator for oversubscribable resources
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513025 24666 sched.cpp:723] Framework registered with 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513056 24666 sched.cpp:737] Scheduler::registered took 18725ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513074 24669 status_update_manager.cpp:174] Pausing sending status updates
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513089 24667 slave.cpp:967] New master detected at master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513105 24667 slave.cpp:1029] Authenticating with master master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513120 24667 slave.cpp:1040] Using default CRAM-MD5 authenticatee
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513169 24667 slave.cpp:1002] Detecting new master
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513192 24663 authenticatee.cpp:121] Creating new client SASL connection
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513260 24667 slave.cpp:5031] Received oversubscribable resources  from the resource estimator
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513324 24666 master.cpp:5943] Authenticating slave(469)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513365 24666 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(958)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513423 24665 authenticator.cpp:98] Creating new server SASL connection
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513484 24665 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513494 24665 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513525 24665 authenticator.cpp:204] Received SASL authentication start
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513563 24665 authenticator.cpp:326] Authentication requires more steps
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513594 24665 authenticatee.cpp:259] Received SASL authentication step
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513635 24665 authenticator.cpp:232] Received SASL authentication step
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513653 24665 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513661 24665 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513667 24665 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513674 24665 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513677 24665 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513680 24665 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513689 24665 authenticator.cpp:318] Authentication success
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513727 24665 authenticatee.cpp:299] Authentication success
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513737 24664 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(958)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513754 24666 master.cpp:5973] Successfully authenticated principal 'test-principal' at slave(469)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513859 24669 slave.cpp:1108] Successfully authenticated with master master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513921 24669 slave.cpp:1511] Will retry registration in 834760ns if necessary
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.513974 24666 master.cpp:4653] Registering agent at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) with id 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.514077 24668 registrar.cpp:464] Applied 1 operations in 12262ns; attempting to update the 'registry'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.514245 24666 log.cpp:577] Attempting to append 395 bytes to the log
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.514282 24666 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.514566 24662 replica.cpp:537] Replica received write request for position 3 from (18487)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.515151 24665 slave.cpp:1511] Will retry registration in 1.465145ms if necessary
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.515202 24667 master.cpp:4641] Ignoring register agent message from slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) as admission is already in progress
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.517513 24663 slave.cpp:1511] Will retry registration in 70.844019ms if necessary
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.517555 24664 master.cpp:4641] Ignoring register agent message from slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) as admission is already in progress
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.518628 24662 leveldb.cpp:341] Persisting action (414 bytes) to leveldb took 4.043654ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.518643 24662 replica.cpp:712] Persisted action at 3
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.518877 24665 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.520764 24665 leveldb.cpp:341] Persisting action (416 bytes) to leveldb took 1.869511ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.520779 24665 replica.cpp:712] Persisted action at 3
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.520784 24665 replica.cpp:697] Replica learned APPEND action at position 3
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521023 24663 registrar.cpp:509] Successfully updated the 'registry' in 6.930176ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521083 24668 log.cpp:596] Attempting to truncate the log to 3
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521152 24665 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521239 24667 master.cpp:4721] Registered agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521272 24665 slave.cpp:3747] Received ping from slave-observer(424)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521280 24664 hierarchical.cpp:473] Added agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 (ip-172-30-2-247.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521340 24665 slave.cpp:1152] Registered with master master@172.30.2.247:42024; given agent ID 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521354 24665 fetcher.cpp:86] Clearing fetcher cache
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521428 24664 hierarchical.cpp:1583] No inverse offers to send out!
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521455 24664 hierarchical.cpp:1162] Performed allocation for agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 in 131318ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521443 24669 replica.cpp:537] Replica received write request for position 4 from (18488)@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521466 24662 status_update_manager.cpp:181] Resuming sending status updates
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521502 24668 master.cpp:5772] Sending 1 offers to framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521553 24665 slave.cpp:1175] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/meta/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/slave.info'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521667 24665 slave.cpp:1212] Forwarding total oversubscribed resources 
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521709 24665 master.cpp:5066] Received update of agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) with total oversubscribed resources 
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521725 24668 sched.cpp:897] Scheduler::resourceOffers took 35814ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521827 24665 hierarchical.cpp:531] Agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 (ip-172-30-2-247.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:45:38]W:	 [Step 10/10] I0619 22:45:38.521860 24665 hierarchical.cpp:1488] No allocations performed
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521870 24665 hierarchical.cpp:1583] No inverse offers to send out!
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521884 24665 hierarchical.cpp:1162] Performed allocation for agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 in 36469ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.521885 24647 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128
[22:45:38]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522244 24666 master.cpp:3457] Processing ACCEPT call for offers: [ 64f1f7ac-e810-4fb1-b549-6e29fc62622b-O0 ] on agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) for framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522267 24666 master.cpp:3095] Authorizing framework principal 'test-principal' to launch task 123bdde2-b542-4206-9554-249c053f63d2
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522642 24666 master.hpp:177] Adding task 123bdde2-b542-4206-9554-249c053f63d2 with resources cpus(*):1; mem(*):128 on agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 (ip-172-30-2-247.mesosphere.io)
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522666 24666 master.cpp:3946] Launching task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024 with resources cpus(*):1; mem(*):128 on agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522780 24662 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 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 from framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522799 24667 slave.cpp:1551] Got assigned task 123bdde2-b542-4206-9554-249c053f63d2 for framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522804 24662 hierarchical.cpp:928] Framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 filtered agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 for 5secs
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.522893 24667 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[22:45:38]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.523059 24667 slave.cpp:1670] Launching task 123bdde2-b542-4206-9554-249c053f63d2 for framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.523108 24667 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[22:45:38]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.523439 24669 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.965378ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.523454 24669 replica.cpp:712] Persisted action at 4
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.523521 24667 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/frameworks/64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000/executors/123bdde2-b542-4206-9554-249c053f63d2/runs/e533d091-9fc2-4161-b6b3-4c99a88be466' to user 'root'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.526239 24665 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.528328 24665 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 2.028744ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.528360 24665 leveldb.cpp:399] Deleting ~2 keys from leveldb took 16691ns
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.528368 24665 replica.cpp:712] Persisted action at 4
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.528374 24665 replica.cpp:697] Replica learned TRUNCATE action at position 4
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.528923 24667 slave.cpp:5734] Launching executor 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/frameworks/64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000/executors/123bdde2-b542-4206-9554-249c053f63d2/runs/e533d091-9fc2-4161-b6b3-4c99a88be466'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.529093 24667 slave.cpp:1896] Queuing task '123bdde2-b542-4206-9554-249c053f63d2' for executor '123bdde2-b542-4206-9554-249c053f63d2' of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.529100 24669 containerizer.cpp:773] Starting container 'e533d091-9fc2-4161-b6b3-4c99a88be466' for executor '123bdde2-b542-4206-9554-249c053f63d2' of framework '64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.529126 24667 slave.cpp:920] Successfully attached file '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/frameworks/64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000/executors/123bdde2-b542-4206-9554-249c053f63d2/runs/e533d091-9fc2-4161-b6b3-4c99a88be466'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.529799 24663 containerizer.cpp:1120] Overwriting environment variable 'LIBPROCESS_IP', original: '172.30.2.247', new: '0.0.0.0', for container e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.530079 24666 containerizer.cpp:1267] Launching 'mesos-containerizer' with flags '--command="{"shell":true,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}" --commands="{"commands":[]}" --help="false" --pipe_read="96" --pipe_write="106" --sandbox="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/frameworks/64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000/executors/123bdde2-b542-4206-9554-249c053f63d2/runs/e533d091-9fc2-4161-b6b3-4c99a88be466" --user="root"'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.530154 24666 linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWUTS | CLONE_NEWNS
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.533272 24662 cni.cpp:683] Bind mounted '/proc/7922/ns/net' to '/var/run/mesos/isolators/network/cni/e533d091-9fc2-4161-b6b3-4c99a88be466/ns' for container e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.533452 24662 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:45:38]W:	 [Step 10/10] I0619 22:45:38.606812 24663 cni.cpp:1066] Got assigned IPv4 address '172.17.42.1/16' from CNI network '__MESOS_TEST__' for container e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.607293 24666 cni.cpp:808] DNS nameservers for container e533d091-9fc2-4161-b6b3-4c99a88be466 are:
[22:45:38]W:	 [Step 10/10] nameserver 172.30.0.2
[22:45:38]W:	 [Step 10/10] Failed to synchronize with agent (it's probably exited)
[22:45:38]W:	 [Step 10/10] E0619 22:45:38.707609 24662 slave.cpp:4039] Container 'e533d091-9fc2-4161-b6b3-4c99a88be466' for executor '123bdde2-b542-4206-9554-249c053f63d2' of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 failed to start: Collect failed: Failed to setup hostname and network files: WARNING: Logging before InitGoogleLogging() is written to STDERR
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.645313  7938 cni.cpp:1449] Set hostname to 'e533d091-9fc2-4161-b6b3-4c99a88be466'
[22:45:38]W:	 [Step 10/10] Mount point '/etc/hostname' does not exist on the host filesystem
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.707772 24669 containerizer.cpp:1576] Destroying container 'e533d091-9fc2-4161-b6b3-4c99a88be466'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.707787 24669 containerizer.cpp:1624] Waiting for the isolators to complete for container 'e533d091-9fc2-4161-b6b3-4c99a88be466'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.708878 24667 cgroups.cpp:2676] Freezing cgroup /cgroup/freezer/mesos/e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.807951 24664 containerizer.cpp:1812] Executor for container 'e533d091-9fc2-4161-b6b3-4c99a88be466' has exited
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.810672 24666 cgroups.cpp:1409] Successfully froze cgroup /cgroup/freezer/mesos/e533d091-9fc2-4161-b6b3-4c99a88be466 after 101.766144ms
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.811637 24668 cgroups.cpp:2694] Thawing cgroup /cgroup/freezer/mesos/e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.812523 24664 cgroups.cpp:1438] Successfully thawed cgroup /cgroup/freezer/mesos/e533d091-9fc2-4161-b6b3-4c99a88be466 after 864us
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.908664 24668 cni.cpp:1217] Unmounted the network namespace handle '/var/run/mesos/isolators/network/cni/e533d091-9fc2-4161-b6b3-4c99a88be466/ns' for container e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.908843 24668 cni.cpp:1228] Removed the container directory '/var/run/mesos/isolators/network/cni/e533d091-9fc2-4161-b6b3-4c99a88be466'
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.909222 24669 provisioner.cpp:411] Ignoring destroy request for unknown container e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.909346 24664 slave.cpp:4152] Executor '123bdde2-b542-4206-9554-249c053f63d2' of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 exited with status 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.909437 24664 slave.cpp:3267] Handling status update TASK_FAILED (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 from @0.0.0.0:0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.909620 24664 slave.cpp:6074] Terminating task 123bdde2-b542-4206-9554-249c053f63d2
[22:45:38]W:	 [Step 10/10] W0619 22:45:38.909713 24665 containerizer.cpp:1418] Ignoring update for unknown container: e533d091-9fc2-4161-b6b3-4c99a88be466
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.909871 24666 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.909888 24666 status_update_manager.cpp:497] Creating StatusUpdate stream for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910080 24666 status_update_manager.cpp:374] Forwarding update TASK_FAILED (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 to the agent
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910163 24665 slave.cpp:3665] Forwarding the update TASK_FAILED (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 to master@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910253 24665 slave.cpp:3559] Status update manager successfully handled status update TASK_FAILED (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910490 24667 master.cpp:5211] Status update TASK_FAILED (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 from agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910512 24667 master.cpp:5259] Forwarding status update TASK_FAILED (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910560 24667 master.cpp:6871] Updating the state of task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (latest state: TASK_FAILED, status update state: TASK_FAILED)
[22:45:38] :	 [Step 10/10] ../../src/tests/containerizer/cni_isolator_tests.cpp:292: Failure
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910698 24668 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 from framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38] :	 [Step 10/10] Value of: statusRunning->state()
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910755 24666 sched.cpp:1005] Scheduler::statusUpdate took 50939ns
[22:45:38] :	 [Step 10/10]   Actual: TASK_FAILED
[22:45:38] :	 [Step 10/10] Expected: TASK_RUNNING
[22:45:38] :	 [Step 10/10] ../../src/tests/containerizer/cni_isolator_tests.cpp:296: Failure
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.910995 24662 master.cpp:4365] Processing ACKNOWLEDGE call 2b27727d-e7cd-4aea-b5a6-a83c83df5f01 for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024 on agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0
[22:45:38] :	 [Step 10/10] Value of: containers.get().size()
[22:45:38] :	 [Step 10/10]   Actual: 0
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911026 24662 master.cpp:6937] Removing task 123bdde2-b542-4206-9554-249c053f63d2 with resources cpus(*):1; mem(*):128 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 on agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:38] :	 [Step 10/10] Expected: 1u
[22:45:38] :	 [Step 10/10] Which is: 1
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911234 24665 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911278 24665 status_update_manager.cpp:528] Cleaning up status update stream for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911402 24669 master.cpp:1406] Framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024 disconnected
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911418 24669 master.cpp:2840] Disconnecting framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911414 24665 slave.cpp:2653] Status update manager successfully handled status update acknowledgement (UUID: 2b27727d-e7cd-4aea-b5a6-a83c83df5f01) for task 123bdde2-b542-4206-9554-249c053f63d2 of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911433 24669 master.cpp:2864] Deactivating framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911453 24665 slave.cpp:6115] Completing task 123bdde2-b542-4206-9554-249c053f63d2
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911470 24665 slave.cpp:4256] Cleaning up executor '123bdde2-b542-4206-9554-249c053f63d2' of framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911548 24669 master.cpp:1419] Giving framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024 0ns to failover
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911583 24662 hierarchical.cpp:375] Deactivated framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911640 24669 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/frameworks/64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000/executors/123bdde2-b542-4206-9554-249c053f63d2/runs/e533d091-9fc2-4161-b6b3-4c99a88be466' for gc 6.99998944950222days in the future
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911680 24665 slave.cpp:4344] Cleaning up framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911689 24669 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/frameworks/64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000/executors/123bdde2-b542-4206-9554-249c053f63d2' for gc 6.99998944832296days in the future
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911738 24664 status_update_manager.cpp:282] Closing status update streams for framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911805 24662 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_VerifyCheckpointedInfo_IIWOru/slaves/64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0/frameworks/64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000' for gc 6.99998944754667days in the future
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911918 24647 slave.cpp:839] Agent terminating
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.911991 24662 master.cpp:1367] Agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) disconnected
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.912009 24662 master.cpp:2899] Disconnecting agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.912029 24662 master.cpp:2918] Deactivating agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 at slave(469)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.912135 24665 hierarchical.cpp:560] Agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0 deactivated
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.912824 24669 master.cpp:5624] Framework failover timeout, removing framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.912842 24669 master.cpp:6354] Removing framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000 (default) at scheduler-17f04bf5-5b53-40c9-8a93-abe9a7966897@172.30.2.247:42024
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.913030 24669 hierarchical.cpp:326] Removed framework 64f1f7ac-e810-4fb1-b549-6e29fc62622b-0000
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.913905 24647 master.cpp:1214] Master terminating
[22:45:38]W:	 [Step 10/10] I0619 22:45:38.914031 24664 hierarchical.cpp:505] Removed agent 64f1f7ac-e810-4fb1-b549-6e29fc62622b-S0
[22:45:38] :	 [Step 10/10] [  FAILED  ] CniIsolatorTest.ROOT_VerifyCheckpointedInfo (457 ms)

[22:45:39] :	 [Step 10/10] [ RUN      ] CniIsolatorTest.ROOT_SlaveRecovery
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.224643 24647 cluster.cpp:155] Creating default 'local' authorizer
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.232614 24647 leveldb.cpp:174] Opened db in 7.839626ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.235198 24647 leveldb.cpp:181] Compacted db in 2.563679ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.235219 24647 leveldb.cpp:196] Created db iterator in 4353ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.235224 24647 leveldb.cpp:202] Seeked to beginning of db in 668ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.235231 24647 leveldb.cpp:271] Iterated through 0 keys in the db in 399ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.235246 24647 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.235555 24662 recover.cpp:451] Starting replica recovery
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.235777 24663 recover.cpp:477] Replica is in EMPTY status
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236134 24669 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (18550)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236197 24663 recover.cpp:197] Received a recover response from a replica in EMPTY status
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236351 24667 recover.cpp:568] Updating replica status to STARTING
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236580 24668 master.cpp:382] Master 032cd99a-1cdc-42d4-b94a-f7b00f37fb52 (ip-172-30-2-247.mesosphere.io) started on 172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236594 24668 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/ghfuib/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/ghfuib/master" --zk_session_timeout="10secs"
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236723 24668 master.cpp:434] Master only allowing authenticated frameworks to register
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236729 24668 master.cpp:448] Master only allowing authenticated agents to register
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236732 24668 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236737 24668 credentials.hpp:37] Loading credentials for authentication from '/tmp/ghfuib/credentials'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236829 24668 master.cpp:506] Using default 'crammd5' authenticator
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236871 24668 master.cpp:578] Using default 'basic' HTTP authenticator
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236946 24668 master.cpp:658] Using default 'basic' HTTP framework authenticator
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.236991 24668 master.cpp:705] Authorization enabled
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.237077 24663 whitelist_watcher.cpp:77] No whitelist given
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.237159 24665 hierarchical.cpp:142] Initialized hierarchical allocator process
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.237638 24667 master.cpp:1969] The newly elected leader is master@172.30.2.247:42024 with id 032cd99a-1cdc-42d4-b94a-f7b00f37fb52
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.237650 24667 master.cpp:1982] Elected as the leading master!
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.237655 24667 master.cpp:1669] Recovering from registrar
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.237700 24669 registrar.cpp:332] Recovering registrar
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.239017 24662 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 2.616259ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.239032 24662 replica.cpp:320] Persisted replica status to STARTING
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.239084 24662 recover.cpp:477] Replica is in STARTING status
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.239437 24669 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (18553)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.239538 24662 recover.cpp:197] Received a recover response from a replica in STARTING status
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.239672 24663 recover.cpp:568] Updating replica status to VOTING
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.241654 24662 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.871972ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.241670 24662 replica.cpp:320] Persisted replica status to VOTING
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.241703 24662 recover.cpp:582] Successfully joined the Paxos group
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.241745 24662 recover.cpp:466] Recover process terminated
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.241880 24662 log.cpp:553] Attempting to start the writer
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.242295 24668 replica.cpp:493] Replica received implicit promise request from (18554)@172.30.2.247:42024 with proposal 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.244303 24668 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.98443ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.244318 24668 replica.cpp:342] Persisted promised to 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.244529 24663 coordinator.cpp:238] Coordinator attempting to fill missing positions
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.245007 24664 replica.cpp:388] Replica received explicit promise request from (18555)@172.30.2.247:42024 for position 0 with proposal 2
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.246898 24664 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.869865ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.246915 24664 replica.cpp:712] Persisted action at 0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.247295 24666 replica.cpp:537] Replica received write request for position 0 from (18556)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.247320 24666 leveldb.cpp:436] Reading position from leveldb took 10783ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.249264 24666 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.93015ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.249279 24666 replica.cpp:712] Persisted action at 0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.249492 24663 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.251349 24663 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.840655ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.251364 24663 replica.cpp:712] Persisted action at 0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.251369 24663 replica.cpp:697] Replica learned NOP action at position 0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.251634 24668 log.cpp:569] Writer started with ending position 0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.251905 24666 leveldb.cpp:436] Reading position from leveldb took 11014ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.252132 24664 registrar.cpp:365] Successfully fetched the registry (0B) in 14.413312ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.252176 24664 registrar.cpp:464] Applied 1 operations in 5009ns; attempting to update the 'registry'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.252378 24663 log.cpp:577] Attempting to append 209 bytes to the log
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.252437 24669 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.252768 24666 replica.cpp:537] Replica received write request for position 1 from (18557)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.254878 24666 leveldb.cpp:341] Persisting action (228 bytes) to leveldb took 2.087874ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.254894 24666 replica.cpp:712] Persisted action at 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.255100 24664 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.256983 24664 leveldb.cpp:341] Persisting action (230 bytes) to leveldb took 1.863178ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.256999 24664 replica.cpp:712] Persisted action at 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257004 24664 replica.cpp:697] Replica learned APPEND action at position 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257231 24663 registrar.cpp:509] Successfully updated the 'registry' in 5.034752ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257283 24663 registrar.cpp:395] Successfully recovered registrar
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257304 24665 log.cpp:596] Attempting to truncate the log to 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257431 24666 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257462 24668 master.cpp:1777] Recovered 0 agents from the Registry (170B) ; allowing 10mins for agents to re-register
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257484 24662 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.257690 24668 replica.cpp:537] Replica received write request for position 2 from (18558)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.259577 24668 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.867119ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.259593 24668 replica.cpp:712] Persisted action at 2
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.259788 24667 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.261890 24667 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 2.084656ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.261920 24667 leveldb.cpp:399] Deleting ~1 keys from leveldb took 13997ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.261929 24667 replica.cpp:712] Persisted action at 2
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.261934 24667 replica.cpp:697] Replica learned TRUNCATE action at position 2
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.269104 24647 containerizer.cpp:201] Using isolation: network/cni,filesystem/posix
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.272172 24647 linux_launcher.cpp:101] Using /cgroup/freezer as the freezer hierarchy for the Linux launcher
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.273219 24647 cluster.cpp:432] Creating default 'local' authorizer
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.273654 24662 slave.cpp:203] Agent started on 471)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.273664 24662 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_SlaveRecovery_UbK9bJ/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/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_SlaveRecovery_UbK9bJ/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="network/cni" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --network_cni_config_dir="/tmp/ghfuib/configs" --network_cni_plugins_dir="/tmp/ghfuib/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_SlaveRecovery_UbK9bJ"
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.273874 24662 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/credential'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.273952 24662 slave.cpp:341] Agent using credential for: test-principal
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.273967 24662 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/http_credentials'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274041 24662 slave.cpp:393] Using default 'basic' HTTP authenticator
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274193 24662 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
[22:45:39]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274448 24647 sched.cpp:224] Version: 1.0.0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274459 24662 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274492 24662 slave.cpp:600] Agent attributes: [  ]
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274500 24662 slave.cpp:605] Agent hostname: ip-172-30-2-247.mesosphere.io
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274618 24669 sched.cpp:328] New master detected at master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274714 24669 sched.cpp:394] Authenticating with master master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274724 24669 sched.cpp:401] Using default CRAM-MD5 authenticatee
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274826 24667 authenticatee.cpp:121] Creating new client SASL connection
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274855 24662 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.274950 24667 master.cpp:5943] Authenticating scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275002 24669 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(961)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275041 24667 status_update_manager.cpp:200] Recovering status update manager
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275116 24668 authenticator.cpp:98] Creating new server SASL connection
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275132 24662 containerizer.cpp:514] Recovering containerizer
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275185 24668 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275197 24668 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275246 24666 authenticator.cpp:204] Received SASL authentication start
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275322 24666 authenticator.cpp:326] Authentication requires more steps
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275370 24666 authenticatee.cpp:259] Received SASL authentication step
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275445 24667 authenticator.cpp:232] Received SASL authentication step
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275462 24667 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275468 24667 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275485 24667 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275492 24667 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275497 24667 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275501 24667 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275511 24667 authenticator.cpp:318] Authentication success
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275563 24667 authenticatee.cpp:299] Authentication success
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275574 24664 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(961)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275586 24665 master.cpp:5973] Successfully authenticated principal 'test-principal' at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275640 24666 sched.cpp:484] Successfully authenticated with master master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275653 24666 sched.cpp:800] Sending SUBSCRIBE call to master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275758 24666 sched.cpp:833] Will retry registration in 1.75141928secs if necessary
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275781 24664 master.cpp:2539] Received SUBSCRIBE call for framework 'default' at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275804 24664 master.cpp:2008] Authorizing framework principal 'test-principal' to receive offers for role '*'
[22:45:39]W:	 [Step 10/10] W0619 22:45:39.275826 24665 cni.cpp:503] The checkpointed CNI plugin output '/var/run/mesos/isolators/network/cni/422a6a27-4327-4dc1-9a4c-7de578226eab/__MESOS_TEST__/eth0/network.info' for container 422a6a27-4327-4dc1-9a4c-7de578226eab does not exist
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275856 24665 cni.cpp:407] Removing unknown orphaned container 422a6a27-4327-4dc1-9a4c-7de578226eab
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.275918 24662 master.cpp:2615] Subscribing framework default with checkpointing enabled and capabilities [  ]
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.278825 24667 hierarchical.cpp:264] Added framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.278898 24667 hierarchical.cpp:1488] No allocations performed
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.278906 24667 hierarchical.cpp:1583] No inverse offers to send out!
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.278916 24667 hierarchical.cpp:1139] Performed allocation for 0 agents in 28334ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.278957 24662 sched.cpp:723] Framework registered with 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279021 24662 sched.cpp:737] Scheduler::registered took 46037ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279216 24669 provisioner.cpp:253] Provisioner recovery complete
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279381 24663 slave.cpp:4845] Finished recovery
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279583 24663 slave.cpp:5017] Querying resource estimator for oversubscribable resources
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279724 24667 status_update_manager.cpp:174] Pausing sending status updates
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279791 24668 slave.cpp:967] New master detected at master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279808 24668 slave.cpp:1029] Authenticating with master master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279826 24668 slave.cpp:1040] Using default CRAM-MD5 authenticatee
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279878 24668 slave.cpp:1002] Detecting new master
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279916 24666 authenticatee.cpp:121] Creating new client SASL connection
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.279953 24668 slave.cpp:5031] Received oversubscribable resources  from the resource estimator
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280045 24666 master.cpp:5943] Authenticating slave(471)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280129 24665 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(962)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280186 24665 authenticator.cpp:98] Creating new server SASL connection
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280266 24665 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280279 24665 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280308 24665 authenticator.cpp:204] Received SASL authentication start
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280345 24665 authenticator.cpp:326] Authentication requires more steps
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280383 24665 authenticatee.cpp:259] Received SASL authentication step
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280447 24669 authenticator.cpp:232] Received SASL authentication step
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280468 24669 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280474 24669 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280483 24669 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280488 24669 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-247' server FQDN: 'ip-172-30-2-247' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280493 24669 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280496 24669 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280504 24669 authenticator.cpp:318] Authentication success
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280544 24669 authenticatee.cpp:299] Authentication success
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280568 24668 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(962)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280596 24665 master.cpp:5973] Successfully authenticated principal 'test-principal' at slave(471)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280673 24669 slave.cpp:1108] Successfully authenticated with master master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280725 24669 slave.cpp:1511] Will retry registration in 8.06966ms if necessary
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280796 24667 master.cpp:4653] Registering agent at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) with id 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.280905 24663 registrar.cpp:464] Applied 1 operations in 11081ns; attempting to update the 'registry'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.281116 24669 log.cpp:577] Attempting to append 395 bytes to the log
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.281182 24664 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.281452 24663 replica.cpp:537] Replica received write request for position 3 from (18575)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.283769 24663 leveldb.cpp:341] Persisting action (414 bytes) to leveldb took 2.297945ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.283785 24663 replica.cpp:712] Persisted action at 3
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.283993 24663 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.285805 24663 leveldb.cpp:341] Persisting action (416 bytes) to leveldb took 1.793213ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.285820 24663 replica.cpp:712] Persisted action at 3
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.285826 24663 replica.cpp:697] Replica learned APPEND action at position 3
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286088 24668 registrar.cpp:509] Successfully updated the 'registry' in 5.161984ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286118 24666 log.cpp:596] Attempting to truncate the log to 3
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286172 24666 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286332 24667 slave.cpp:3747] Received ping from slave-observer(426)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286325 24665 master.cpp:4721] Registered agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286382 24668 hierarchical.cpp:473] Added agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 (ip-172-30-2-247.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286411 24667 slave.cpp:1152] Registered with master master@172.30.2.247:42024; given agent ID 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286424 24667 fetcher.cpp:86] Clearing fetcher cache
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286480 24665 status_update_manager.cpp:181] Resuming sending status updates
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286545 24669 replica.cpp:537] Replica received write request for position 4 from (18576)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286556 24668 hierarchical.cpp:1583] No inverse offers to send out!
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286579 24668 hierarchical.cpp:1162] Performed allocation for agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 in 176726ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286625 24667 slave.cpp:1175] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/slave.info'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286660 24663 master.cpp:5772] Sending 1 offers to framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286782 24667 slave.cpp:1212] Forwarding total oversubscribed resources 
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286842 24667 master.cpp:5066] Received update of agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) with total oversubscribed resources 
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286912 24663 sched.cpp:897] Scheduler::resourceOffers took 41729ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.286981 24667 hierarchical.cpp:531] Agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 (ip-172-30-2-247.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:45:39]W:	 [Step 10/10] I0619 22:45:39.287026 24667 hierarchical.cpp:1488] No allocations performed
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287036 24667 hierarchical.cpp:1583] No inverse offers to send out!
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287051 24667 hierarchical.cpp:1162] Performed allocation for agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 in 40073ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287082 24647 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128
[22:45:39]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287443 24668 master.cpp:3457] Processing ACCEPT call for offers: [ 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-O0 ] on agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) for framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287467 24668 master.cpp:3095] Authorizing framework principal 'test-principal' to launch task 44eba68b-0f7c-437f-935f-26a52ac3f64b
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287804 24667 master.hpp:177] Adding task 44eba68b-0f7c-437f-935f-26a52ac3f64b with resources cpus(*):1; mem(*):128 on agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 (ip-172-30-2-247.mesosphere.io)
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287829 24667 master.cpp:3946] Launching task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024 with resources cpus(*):1; mem(*):128 on agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287947 24664 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 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 from framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287981 24665 slave.cpp:1551] Got assigned task 44eba68b-0f7c-437f-935f-26a52ac3f64b for framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.287981 24664 hierarchical.cpp:928] Framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 filtered agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 for 5secs
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288043 24665 slave.cpp:5654] Checkpointing FrameworkInfo to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/framework.info'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288200 24665 slave.cpp:5665] Checkpointing framework pid 'scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024' to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/framework.pid'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288331 24665 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[22:45:39]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288467 24669 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.901433ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288480 24669 replica.cpp:712] Persisted action at 4
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288480 24665 slave.cpp:1670] Launching task 44eba68b-0f7c-437f-935f-26a52ac3f64b for framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288516 24665 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[22:45:39]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288709 24669 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.288784 24665 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' to user 'root'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.290657 24669 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.915037ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.290714 24669 leveldb.cpp:399] Deleting ~2 keys from leveldb took 27510ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.290726 24669 replica.cpp:712] Persisted action at 4
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.290736 24669 replica.cpp:697] Replica learned TRUNCATE action at position 4
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.292919 24665 slave.cpp:6136] Checkpointing ExecutorInfo to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/executor.info'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.293200 24665 slave.cpp:5734] Launching executor 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.293373 24669 containerizer.cpp:773] Starting container 'ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' for executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework '032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.293403 24665 slave.cpp:6159] Checkpointing TaskInfo to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d/tasks/44eba68b-0f7c-437f-935f-26a52ac3f64b/task.info'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.293581 24665 slave.cpp:1896] Queuing task '44eba68b-0f7c-437f-935f-26a52ac3f64b' for executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.293622 24665 slave.cpp:920] Successfully attached file '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.294059 24662 containerizer.cpp:1120] Overwriting environment variable 'LIBPROCESS_IP', original: '172.30.2.247', new: '0.0.0.0', for container ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.294361 24664 containerizer.cpp:1267] Launching 'mesos-containerizer' with flags '--command="{"shell":true,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}" --commands="{"commands":[]}" --help="false" --pipe_read="96" --pipe_write="107" --sandbox="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d" --user="root"'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.294427 24664 linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWUTS | CLONE_NEWNS
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.296911 24664 containerizer.cpp:1302] Checkpointing executor's forked pid 7982 to '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d/pids/forked.pid'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.297456 24663 cni.cpp:683] Bind mounted '/proc/7982/ns/net' to '/var/run/mesos/isolators/network/cni/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d/ns' for container ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.297610 24663 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:45:39]W:	 [Step 10/10] I0619 22:45:39.311471 24667 cni.cpp:1066] Got assigned IPv4 address '172.17.42.1/16' from CNI network '__MESOS_TEST__' for container ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.311671 24667 cni.cpp:1217] Unmounted the network namespace handle '/var/run/mesos/isolators/network/cni/422a6a27-4327-4dc1-9a4c-7de578226eab/ns' for container 422a6a27-4327-4dc1-9a4c-7de578226eab
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.311774 24667 cni.cpp:1228] Removed the container directory '/var/run/mesos/isolators/network/cni/422a6a27-4327-4dc1-9a4c-7de578226eab'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.311911 24667 cni.cpp:808] DNS nameservers for container ef0b6221-1073-42f0-adfc-cfe75ddb3a5d are:
[22:45:39]W:	 [Step 10/10] nameserver 172.30.0.2
[22:45:39]W:	 [Step 10/10] EFailed to synchronize with agent (it's probably exited)0619 22:45:39.412294 24666 slave.cpp:4039] Container 'ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' for executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 failed to start: Collect failed: Failed to setup hostname and network files: WARNING: Logging before InitGoogleLogging() is written to STDERR
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.352311  7998 cni.cpp:1449] Set hostname to 'ef0b6221-1073-42f0-adfc-cfe75ddb3a5d'
[22:45:39]W:	 [Step 10/10] Mount point '/etc/hostname' does not exist on the host filesystem
[22:45:39]W:	 [Step 10/10] 
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.412427 24664 containerizer.cpp:1576] Destroying container 'ef0b6221-1073-42f0-adfc-cfe75ddb3a5d'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.412444 24664 containerizer.cpp:1624] Waiting for the isolators to complete for container 'ef0b6221-1073-42f0-adfc-cfe75ddb3a5d'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.413815 24662 cgroups.cpp:2676] Freezing cgroup /cgroup/freezer/mesos/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.512704 24665 containerizer.cpp:1812] Executor for container 'ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' has exited
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.516521 24662 cgroups.cpp:1409] Successfully froze cgroup /cgroup/freezer/mesos/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d after 102.685184ms
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.517462 24664 cgroups.cpp:2694] Thawing cgroup /cgroup/freezer/mesos/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.518301 24662 cgroups.cpp:1438] Successfully thawed cgroup /cgroup/freezer/mesos/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d after 813824ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.614039 24664 cni.cpp:1217] Unmounted the network namespace handle '/var/run/mesos/isolators/network/cni/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d/ns' for container ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.614209 24664 cni.cpp:1228] Removed the container directory '/var/run/mesos/isolators/network/cni/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.614532 24662 provisioner.cpp:411] Ignoring destroy request for unknown container ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.614665 24668 slave.cpp:4152] Executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 exited with status 1
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.614742 24668 slave.cpp:3267] Handling status update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 from @0.0.0.0:0
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.614964 24669 slave.cpp:6074] Terminating task 44eba68b-0f7c-437f-935f-26a52ac3f64b
[22:45:39]W:	 [Step 10/10] W0619 22:45:39.615054 24669 containerizer.cpp:1418] Ignoring update for unknown container: ef0b6221-1073-42f0-adfc-cfe75ddb3a5d
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.615197 24668 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.615211 24668 status_update_manager.cpp:497] Creating StatusUpdate stream for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.615552 24668 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.623800 24668 status_update_manager.cpp:374] Forwarding update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 to the agent
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.623888 24662 slave.cpp:3665] Forwarding the update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 to master@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.623988 24662 slave.cpp:3559] Status update manager successfully handled status update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624162 24668 master.cpp:5211] Status update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 from agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624181 24668 master.cpp:5259] Forwarding status update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624243 24668 master.cpp:6871] Updating the state of task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (latest state: TASK_FAILED, status update state: TASK_FAILED)
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624356 24666 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 from framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624442 24669 sched.cpp:1005] Scheduler::statusUpdate took 38999ns
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624614 24664 master.cpp:4365] Processing ACKNOWLEDGE call addda641-2dda-4d21-bc97-f2d8f9e28fe7 for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024 on agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0
[22:45:39] :	 [Step 10/10] ../../src/tests/containerizer/cni_isolator_tests.cpp:487: Failure
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624634 24664 master.cpp:6937] Removing task 44eba68b-0f7c-437f-935f-26a52ac3f64b with resources cpus(*):1; mem(*):128 of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 on agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:39] :	 [Step 10/10] Value of: statusRunning->state()
[22:45:39] :	 [Step 10/10]   Actual: TASK_FAILED
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624804 24665 status_update_manager.cpp:392] Received status update acknowledgement (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39] :	 [Step 10/10] Expected: TASK_RUNNING
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.624847 24665 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_FAILED (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628197 24665 status_update_manager.cpp:528] Cleaning up status update stream for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628276 24665 slave.cpp:2653] Status update manager successfully handled status update acknowledgement (UUID: addda641-2dda-4d21-bc97-f2d8f9e28fe7) for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628291 24665 slave.cpp:6115] Completing task 44eba68b-0f7c-437f-935f-26a52ac3f64b
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628304 24665 slave.cpp:4256] Cleaning up executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628487 24669 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' for gc 6.99999272627556days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628530 24669 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b' for gc 6.99999272575111days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628592 24663 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' for gc 6.99999272505778days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628623 24665 slave.cpp:4344] Cleaning up framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628635 24663 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b' for gc 6.9999927244563days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628679 24663 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000' for gc 6.99999272379556days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628686 24667 status_update_manager.cpp:282] Closing status update streams for framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628693 24665 slave.cpp:839] Agent terminating
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628718 24663 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000' for gc 6.9999927235763days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628746 24665 master.cpp:1367] Agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io) disconnected
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628760 24665 master.cpp:2899] Disconnecting agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628783 24665 master.cpp:2918] Deactivating agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 at slave(471)@172.30.2.247:42024 (ip-172-30-2-247.mesosphere.io)
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.628832 24665 hierarchical.cpp:560] Agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0 deactivated
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.629724 24647 containerizer.cpp:201] Using isolation: network/cni,filesystem/posix
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.633214 24647 linux_launcher.cpp:101] Using /cgroup/freezer as the freezer hierarchy for the Linux launcher
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.634099 24647 cluster.cpp:432] Creating default 'local' authorizer
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.634585 24664 slave.cpp:203] Agent started on 472)@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.634599 24664 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_SlaveRecovery_UbK9bJ/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/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_SlaveRecovery_UbK9bJ/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="network/cni" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --network_cni_config_dir="/tmp/ghfuib/configs" --network_cni_plugins_dir="/tmp/ghfuib/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_SlaveRecovery_UbK9bJ"
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.634822 24664 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/credential'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.634886 24664 slave.cpp:341] Agent using credential for: test-principal
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.634897 24664 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/http_credentials'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.634953 24664 slave.cpp:393] Using default 'basic' HTTP authenticator
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.635114 24664 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
[22:45:39]W:	 [Step 10/10] Trying semicolon-delimited string format instead
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.635422 24664 slave.cpp:592] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.635444 24664 slave.cpp:600] Agent attributes: [  ]
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.635449 24664 slave.cpp:605] Agent hostname: ip-172-30-2-247.mesosphere.io
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.635941 24668 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.635964 24668 state.cpp:697] No checkpointed resources found at '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/resources/resources.info'
[22:45:39]W:	 [Step 10/10] W0619 22:45:39.636117 24669 master.cpp:4232] Cannot kill task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024 because it is unknown; performing reconciliation
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636142 24669 master.cpp:5510] Performing explicit task state reconciliation for 1 tasks of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39] :	 [Step 10/10] ../../src/tests/containerizer/cni_isolator_tests.cpp:504: Failure
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636162 24669 master.cpp:5600] Sending explicit reconciliation state TASK_LOST for task 44eba68b-0f7c-437f-935f-26a52ac3f64b of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39] :	 [Step 10/10] Value of: statusKilled->state()
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636317 24669 sched.cpp:1005] Scheduler::statusUpdate took 28596ns
[22:45:39] :	 [Step 10/10]   Actual: TASK_LOST
[22:45:39] :	 [Step 10/10] Expected: TASK_KILLED
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636548 24647 sched.cpp:1964] Asked to stop the driver
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636605 24669 sched.cpp:1167] Stopping framework '032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000'
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636728 24662 master.cpp:6342] Processing TEARDOWN call for framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] W0619 22:45:39.636739 24668 state.cpp:544] Failed to find executor libprocess pid/http marker file
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636747 24662 master.cpp:6354] Removing framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 (default) at scheduler-fb3e96c6-1106-4910-80d7-e83d75960307@172.30.2.247:42024
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636823 24664 hierarchical.cpp:375] Deactivated framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.636973 24667 hierarchical.cpp:326] Removed framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637154 24663 fetcher.cpp:86] Clearing fetcher cache
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637192 24663 slave.cpp:4933] Recovering framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637208 24663 slave.cpp:5858] Recovering executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637316 24663 slave.cpp:6074] Terminating task 44eba68b-0f7c-437f-935f-26a52ac3f64b
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637331 24663 slave.cpp:6115] Completing task 44eba68b-0f7c-437f-935f-26a52ac3f64b
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637421 24666 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' for gc 6.99999262296296days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637454 24666 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b/runs/ef0b6221-1073-42f0-adfc-cfe75ddb3a5d' for gc 6.99999262252444days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637460 24663 slave.cpp:4344] Cleaning up framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637477 24666 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b' for gc 6.99999262231407days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637514 24666 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000/executors/44eba68b-0f7c-437f-935f-26a52ac3f64b' for gc 6.99999262212741days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637534 24667 status_update_manager.cpp:282] Closing status update streams for framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637547 24666 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000' for gc 6.99999262155259days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637574 24666 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/CniIsolatorTest_ROOT_SlaveRecovery_UbK9bJ/meta/slaves/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0/frameworks/032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000' for gc 6.99999262134222days in the future
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637648 24668 status_update_manager.cpp:200] Recovering status update manager
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637660 24668 status_update_manager.cpp:208] Recovering executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637676 24668 status_update_manager.cpp:233] Skipping recovering updates of executor '44eba68b-0f7c-437f-935f-26a52ac3f64b' of framework 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-0000 because its latest run ef0b6221-1073-42f0-adfc-cfe75ddb3a5d is completed
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.637729 24663 slave.cpp:839] Agent terminating
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.639163 24647 master.cpp:1214] Master terminating
[22:45:39]W:	 [Step 10/10] I0619 22:45:39.639279 24667 hierarchical.cpp:505] Removed agent 032cd99a-1cdc-42d4-b94a-f7b00f37fb52-S0
[22:45:39] :	 [Step 10/10] [  FAILED  ] CniIsolatorTest.ROOT_SlaveRecovery (418 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:36

Updated:: 26/Apr/17 17:00

Resolved:: 22/Jun/16 23:04