[MESOS-5176] LinuxFilesystemIsolatorTest.ROOT_RecoverOrphanedPersistentVolume is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Duplicate
Affects Version/s: None
Fix Version/s: None
Component/s: test
Labels:
Environment:

CentOS 7, with libevent and SSL enabled

Epic Link:
flaky
Sprint:
Mesosphere Sprint 37

Description

Observed on the internal Mesosphere CI:

[07:10:58] :	 [Step 11/11] [ RUN      ] LinuxFilesystemIsolatorTest.ROOT_RecoverOrphanedPersistentVolume
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.289384 32129 cluster.cpp:149] Creating default 'local' authorizer
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.317526 32129 leveldb.cpp:174] Opened db in 27.91929ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.318943 32129 leveldb.cpp:181] Compacted db in 1.383973ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.318989 32129 leveldb.cpp:196] Created db iterator in 18603ns
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.319000 32129 leveldb.cpp:202] Seeked to beginning of db in 1529ns
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.319008 32129 leveldb.cpp:271] Iterated through 0 keys in the db in 358ns
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.319046 32129 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.319627 32143 recover.cpp:447] Starting replica recovery
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.319852 32143 recover.cpp:473] Replica is in EMPTY status
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.320796 32145 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (17047)@172.30.2.121:48158
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.321202 32146 recover.cpp:193] Received a recover response from a replica in EMPTY status
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.321650 32150 recover.cpp:564] Updating replica status to STARTING
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323005 32149 master.cpp:382] Master 57a2cf4e-da76-4801-a887-c0c84ad59d0d (ip-172-30-2-121.mesosphere.io) started on 172.30.2.121:48158
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323022 32149 master.cpp:384] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/fWC4sn/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/fWC4sn/master" --zk_session_timeout="10secs"
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323227 32149 master.cpp:433] Master only allowing authenticated frameworks to register
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323237 32149 master.cpp:438] Master only allowing authenticated agents to register
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323243 32149 credentials.hpp:37] Loading credentials for authentication from '/tmp/fWC4sn/credentials'
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323498 32149 master.cpp:480] Using default 'crammd5' authenticator
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323616 32149 master.cpp:551] Using default 'basic' HTTP authenticator
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323739 32149 master.cpp:589] Authorization enabled
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323884 32150 whitelist_watcher.cpp:77] No whitelist given
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.323920 32143 hierarchical.cpp:142] Initialized hierarchical allocator process
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.324103 32148 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 2.27166ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.324126 32148 replica.cpp:320] Persisted replica status to STARTING
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.324322 32146 recover.cpp:473] Replica is in STARTING status
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.325204 32143 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (17049)@172.30.2.121:48158
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.325527 32145 recover.cpp:193] Received a recover response from a replica in STARTING status
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.325860 32150 master.cpp:1832] The newly elected leader is master@172.30.2.121:48158 with id 57a2cf4e-da76-4801-a887-c0c84ad59d0d
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.325886 32150 master.cpp:1845] Elected as the leading master!
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.325899 32150 master.cpp:1532] Recovering from registrar
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.326045 32143 registrar.cpp:331] Recovering registrar
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.326062 32144 recover.cpp:564] Updating replica status to VOTING
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.327460 32150 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.179112ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.327482 32150 replica.cpp:320] Persisted replica status to VOTING
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.327584 32144 recover.cpp:578] Successfully joined the Paxos group
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.327760 32144 recover.cpp:462] Recover process terminated
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.328178 32146 log.cpp:659] Attempting to start the writer
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.329216 32146 replica.cpp:493] Replica received implicit promise request from (17050)@172.30.2.121:48158 with proposal 1
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.330338 32146 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.091942ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.330361 32146 replica.cpp:342] Persisted promised to 1
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.330871 32145 coordinator.cpp:238] Coordinator attempting to fill missing positions
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.331970 32149 replica.cpp:388] Replica received explicit promise request from (17051)@172.30.2.121:48158 for position 0 with proposal 2
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.333112 32149 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.108612ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.333135 32149 replica.cpp:712] Persisted action at 0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.334074 32149 replica.cpp:537] Replica received write request for position 0 from (17052)@172.30.2.121:48158
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.334121 32149 leveldb.cpp:436] Reading position from leveldb took 22740ns
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.335244 32149 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.092622ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.335268 32149 replica.cpp:712] Persisted action at 0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.335729 32148 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.336899 32148 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.141951ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.336923 32148 replica.cpp:712] Persisted action at 0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.336938 32148 replica.cpp:697] Replica learned NOP action at position 0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.337348 32150 log.cpp:675] Writer started with ending position 0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.338287 32145 leveldb.cpp:436] Reading position from leveldb took 24262ns
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.339108 32148 registrar.cpp:364] Successfully fetched the registry (0B) in 13.024768ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.339198 32148 registrar.cpp:463] Applied 1 operations in 23802ns; attempting to update the 'registry'
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.339870 32145 log.cpp:683] Attempting to append 210 bytes to the log
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.339967 32148 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.340584 32143 replica.cpp:537] Replica received write request for position 1 from (17053)@172.30.2.121:48158
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.341732 32143 leveldb.cpp:341] Persisting action (229 bytes) to leveldb took 1.119048ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.341756 32143 replica.cpp:712] Persisted action at 1
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.342329 32147 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.343457 32147 leveldb.cpp:341] Persisting action (231 bytes) to leveldb took 1.099848ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.343480 32147 replica.cpp:712] Persisted action at 1
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.343495 32147 replica.cpp:697] Replica learned APPEND action at position 1
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.344277 32146 registrar.cpp:508] Successfully updated the 'registry' in 5.03296ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.344406 32146 registrar.cpp:394] Successfully recovered registrar
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.344476 32149 log.cpp:702] Attempting to truncate the log to 1
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.344583 32150 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.344920 32144 master.cpp:1640] Recovered 0 agents from the Registry (171B) ; allowing 10mins for agents to re-register
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.344954 32148 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.345376 32149 replica.cpp:537] Replica received write request for position 2 from (17054)@172.30.2.121:48158
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.346536 32149 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.128388ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.346560 32149 replica.cpp:712] Persisted action at 2
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.347036 32149 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.348248 32149 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.185295ms
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.348297 32149 leveldb.cpp:399] Deleting ~1 keys from leveldb took 26602ns
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.348312 32149 replica.cpp:712] Persisted action at 2
[07:10:58]W:	 [Step 11/11] I0410 07:10:58.348328 32149 replica.cpp:697] Replica learned TRUNCATE action at position 2
[07:10:59]W:	 [Step 11/11] I0410 07:10:59.325145 32149 hierarchical.cpp:1488] No resources available to allocate!
[07:10:59]W:	 [Step 11/11] I0410 07:10:59.325237 32149 hierarchical.cpp:1139] Performed allocation for 0 agents in 202090ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.048188 32129 linux.cpp:81] Making '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP' a shared mount
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.063829 32129 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.066910 32149 slave.cpp:201] Agent started on 456)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.066932 32149 slave.cpp:202] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/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_credentials="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/disk,filesystem/linux" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk(role1):1024" --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/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP"
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.067283 32149 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/credential'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.067490 32149 slave.cpp:339] Agent using credential for: test-principal
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.067514 32149 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/http_credentials'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.067737 32149 slave.cpp:391] Using default 'basic' HTTP authenticator
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068104 32149 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk(role1):1024
[07:11:00]W:	 [Step 11/11] Trying semicolon-delimited string format instead
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068159 32129 sched.cpp:224] Version: 0.29.0
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068557 32149 slave.cpp:590] Agent resources: cpus(*):2; mem(*):1024; disk(role1):1024; ports(*):[31000-32000]
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068617 32149 slave.cpp:598] Agent attributes: [  ]
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068632 32149 slave.cpp:603] Agent hostname: ip-172-30-2-121.mesosphere.io
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068881 32143 sched.cpp:328] New master detected at master@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068964 32143 sched.cpp:384] Authenticating with master master@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.068977 32143 sched.cpp:391] Using default CRAM-MD5 authenticatee
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.069211 32146 authenticatee.cpp:121] Creating new client SASL connection
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.069533 32145 master.cpp:5695] Authenticating scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.069634 32143 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(930)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.069886 32144 authenticator.cpp:98] Creating new server SASL connection
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070024 32150 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070236 32144 status_update_manager.cpp:200] Recovering status update manager
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070240 32145 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070273 32145 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070379 32143 authenticator.cpp:203] Received SASL authentication start
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070420 32143 authenticator.cpp:325] Authentication requires more steps
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070483 32146 containerizer.cpp:423] Recovering containerizer
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070524 32144 authenticatee.cpp:258] Received SASL authentication step
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070624 32144 authenticator.cpp:231] Received SASL authentication step
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070648 32144 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-121.mesosphere.io' server FQDN: 'ip-172-30-2-121.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070657 32144 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070703 32144 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070731 32144 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-121.mesosphere.io' server FQDN: 'ip-172-30-2-121.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070749 32144 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070754 32144 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070765 32144 authenticator.cpp:317] Authentication success
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070842 32143 authenticatee.cpp:298] Authentication success
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070881 32149 master.cpp:5725] Successfully authenticated principal 'test-principal' at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.070942 32148 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(930)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.071214 32147 sched.cpp:474] Successfully authenticated with master master@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.071231 32147 sched.cpp:779] Sending SUBSCRIBE call to master@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.071308 32147 sched.cpp:812] Will retry registration in 544.572419ms if necessary
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.071419 32149 master.cpp:2362] Received SUBSCRIBE call for framework 'default' at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.071493 32149 master.cpp:1871] Authorizing framework principal 'test-principal' to receive offers for role 'role1'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.071815 32149 master.cpp:2433] Subscribing framework default with checkpointing enabled and capabilities [  ]
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.072386 32147 sched.cpp:706] Framework registered with 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.072392 32144 hierarchical.cpp:264] Added framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.072470 32147 sched.cpp:720] Scheduler::registered took 62502ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.072499 32144 hierarchical.cpp:1488] No resources available to allocate!
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.072540 32144 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.072616 32144 hierarchical.cpp:1139] Performed allocation for 0 agents in 197483ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.073873 32146 provisioner.cpp:245] Provisioner recovery complete
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.074198 32148 slave.cpp:4784] Finished recovery
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.074604 32148 slave.cpp:4956] Querying resource estimator for oversubscribable resources
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.074805 32147 status_update_manager.cpp:174] Pausing sending status updates
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.074806 32148 slave.cpp:939] New master detected at master@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.074878 32148 slave.cpp:1002] Authenticating with master master@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.074901 32148 slave.cpp:1007] Using default CRAM-MD5 authenticatee
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075027 32148 slave.cpp:975] Detecting new master
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075052 32144 authenticatee.cpp:121] Creating new client SASL connection
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075178 32148 slave.cpp:4970] Received oversubscribable resources  from the resource estimator
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075300 32150 master.cpp:5695] Authenticating slave(456)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075387 32146 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(931)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075572 32148 authenticator.cpp:98] Creating new server SASL connection
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075839 32149 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075858 32149 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075928 32149 authenticator.cpp:203] Received SASL authentication start
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.075965 32149 authenticator.cpp:325] Authentication requires more steps
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076040 32149 authenticatee.cpp:258] Received SASL authentication step
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076130 32149 authenticator.cpp:231] Received SASL authentication step
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076159 32149 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-121.mesosphere.io' server FQDN: 'ip-172-30-2-121.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076169 32149 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076192 32149 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076211 32149 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-121.mesosphere.io' server FQDN: 'ip-172-30-2-121.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076220 32149 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076225 32149 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076234 32149 authenticator.cpp:317] Authentication success
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076326 32143 authenticatee.cpp:298] Authentication success
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076331 32148 master.cpp:5725] Successfully authenticated principal 'test-principal' at slave(456)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076359 32147 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(931)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076658 32148 slave.cpp:1072] Successfully authenticated with master master@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076797 32148 slave.cpp:1468] Will retry registration in 2.864508ms if necessary
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.076948 32149 master.cpp:4406] Registering agent at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io) with id 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.077338 32145 registrar.cpp:463] Applied 1 operations in 56533ns; attempting to update the 'registry'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.078030 32149 log.cpp:683] Attempting to append 400 bytes to the log
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.078142 32150 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.078819 32144 replica.cpp:537] Replica received write request for position 3 from (17070)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.079618 32144 leveldb.cpp:341] Persisting action (419 bytes) to leveldb took 766757ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.079639 32144 replica.cpp:712] Persisted action at 3
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.080257 32143 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.080281 32146 slave.cpp:1468] Will retry registration in 17.100417ms if necessary
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.080428 32147 master.cpp:4394] Ignoring register agent message from slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io) as admission is already in progress
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.080947 32143 leveldb.cpp:341] Persisting action (421 bytes) to leveldb took 661588ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.080966 32143 replica.cpp:712] Persisted action at 3
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.080982 32143 replica.cpp:697] Replica learned APPEND action at position 3
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.082180 32145 registrar.cpp:508] Successfully updated the 'registry' in 4.772864ms
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.082388 32148 log.cpp:702] Attempting to truncate the log to 3
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.082489 32144 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.082860 32144 slave.cpp:3675] Received ping from slave-observer(424)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.082981 32149 master.cpp:4474] Registered agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io) with cpus(*):2; mem(*):1024; disk(role1):1024; ports(*):[31000-32000]
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083041 32147 slave.cpp:1116] Registered with master master@172.30.2.121:48158; given agent ID 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083081 32147 fetcher.cpp:81] Clearing fetcher cache
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083138 32143 hierarchical.cpp:473] Added agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 (ip-172-30-2-121.mesosphere.io) with cpus(*):2; mem(*):1024; disk(role1):1024; ports(*):[31000-32000] (allocated: )
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083235 32148 replica.cpp:537] Replica received write request for position 4 from (17071)@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083251 32146 status_update_manager.cpp:181] Resuming sending status updates
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083376 32147 slave.cpp:1139] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/slave.info'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083588 32147 slave.cpp:1176] Forwarding total oversubscribed resources 
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083712 32147 master.cpp:4818] Received update of agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io) with total oversubscribed resources 
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083824 32143 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083894 32143 hierarchical.cpp:1162] Performed allocation for agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 in 700132ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083921 32148 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 648211ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.083946 32148 replica.cpp:712] Persisted action at 4
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.084077 32147 master.cpp:5524] Sending 1 offers to framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.084343 32143 hierarchical.cpp:531] Agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 (ip-172-30-2-121.mesosphere.io) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(role1):1024; ports(*):[31000-32000], allocated: disk(role1):1024; cpus(*):2; mem(*):1024; ports(*):[31000-32000])
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.084489 32143 hierarchical.cpp:1488] No resources available to allocate!
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.084522 32143 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.084561 32143 hierarchical.cpp:1162] Performed allocation for agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 in 185163ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.084559 32149 sched.cpp:876] Scheduler::resourceOffers took 177926ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.084712 32148 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.085146 32129 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:512
[07:11:00]W:	 [Step 11/11] Trying semicolon-delimited string format instead
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.085340 32148 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 605285ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.085388 32148 leveldb.cpp:399] Deleting ~2 keys from leveldb took 28816ns
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.085403 32148 replica.cpp:712] Persisted action at 4
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.085418 32148 replica.cpp:697] Replica learned TRUNCATE action at position 4
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.086369 32147 master.cpp:3304] Processing ACCEPT call for offers: [ 57a2cf4e-da76-4801-a887-c0c84ad59d0d-O0 ] on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io) for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.086470 32147 master.cpp:3062] Authorizing principal 'test-principal' to create volumes
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.086611 32147 master.cpp:2907] Authorizing framework principal 'test-principal' to launch task faa8593f-f2fa-4dc7-804a-fc6d72d04868 as user 'root'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.087605 32150 master.cpp:3633] Applying CREATE operation for volumes disk(role1)[id1:path1]:64 from framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158 to agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io)
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.087908 32150 master.cpp:6763] Sending checkpointed resources disk(role1)[id1:path1]:64 to agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io)
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.088402 32147 slave.cpp:2534] Updated checkpointed resources from  to disk(role1)[id1:path1]:64
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.088814 32150 master.hpp:177] Adding task faa8593f-f2fa-4dc7-804a-fc6d72d04868 with resources cpus(*):1; mem(*):512; disk(role1)[id1:path1]:64 on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 (ip-172-30-2-121.mesosphere.io)
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.088950 32150 master.cpp:3789] Launching task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158 with resources cpus(*):1; mem(*):512; disk(role1)[id1:path1]:64 on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io)
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.089087 32146 hierarchical.cpp:654] Updated allocation of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 from disk(role1):1024; cpus(*):2; mem(*):1024; ports(*):[31000-32000] to disk(role1):960; cpus(*):2; mem(*):1024; ports(*):[31000-32000]; disk(role1)[id1:path1]:64
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.089273 32148 slave.cpp:1508] Got assigned task faa8593f-f2fa-4dc7-804a-fc6d72d04868 for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.089373 32148 slave.cpp:5506] Checkpointing FrameworkInfo to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/framework.info'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.089550 32145 hierarchical.cpp:891] Recovered disk(role1):960; cpus(*):1; mem(*):512; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(role1):960; ports(*):[31000-32000]; disk(role1)[id1:path1]:64, allocated: disk(role1)[id1:path1]:64; cpus(*):1; mem(*):512) on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 from framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.089601 32145 hierarchical.cpp:928] Framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 filtered agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 for 5secs
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.089632 32148 slave.cpp:5517] Checkpointing framework pid 'scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158' to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/framework.pid'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.089885 32148 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[07:11:00]W:	 [Step 11/11] Trying semicolon-delimited string format instead
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.090648 32148 slave.cpp:1627] Launching task faa8593f-f2fa-4dc7-804a-fc6d72d04868 for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.090755 32148 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[07:11:00]W:	 [Step 11/11] Trying semicolon-delimited string format instead
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.091497 32148 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4' to user 'root'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.096308 32148 slave.cpp:5958] Checkpointing ExecutorInfo to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/executor.info'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.096735 32148 slave.cpp:5586] Launching executor faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.097268 32143 containerizer.cpp:682] Starting container '7817548e-0ec3-4273-89f6-006f3b27f8f4' for executor 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' of framework '57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.097317 32148 slave.cpp:5981] Checkpointing TaskInfo to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4/tasks/faa8593f-f2fa-4dc7-804a-fc6d72d04868/task.info'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.097623 32148 slave.cpp:1845] Queuing task 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' for executor 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.097736 32148 slave.cpp:892] Successfully attached file '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.097898 32146 provisioner.cpp:285] Provisioning image rootfs '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/provisioner/containers/7817548e-0ec3-4273-89f6-006f3b27f8f4/backends/copy/rootfses/2d0cdbbf-1df5-48a3-aec2-02272cf1de44' for container 7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.098497 32149 copy.cpp:127] Copying layer path '/tmp/fWC4sn/test_image' to rootfs '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/provisioner/containers/7817548e-0ec3-4273-89f6-006f3b27f8f4/backends/copy/rootfses/2d0cdbbf-1df5-48a3-aec2-02272cf1de44'
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.327247 32148 hierarchical.cpp:1674] Filtered offer with disk(role1):960; cpus(*):1; mem(*):512; ports(*):[31000-32000] on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.327353 32148 hierarchical.cpp:1488] No resources available to allocate!
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.327405 32148 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:00]W:	 [Step 11/11] I0410 07:11:00.327522 32148 hierarchical.cpp:1139] Performed allocation for 1 agents in 1.235386ms
[07:11:01]W:	 [Step 11/11] I0410 07:11:01.328958 32143 hierarchical.cpp:1674] Filtered offer with disk(role1):960; cpus(*):1; mem(*):512; ports(*):[31000-32000] on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:01]W:	 [Step 11/11] I0410 07:11:01.329033 32143 hierarchical.cpp:1488] No resources available to allocate!
[07:11:01]W:	 [Step 11/11] I0410 07:11:01.329068 32143 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:01]W:	 [Step 11/11] I0410 07:11:01.329134 32143 hierarchical.cpp:1139] Performed allocation for 1 agents in 818287ns
[07:11:02]W:	 [Step 11/11] I0410 07:11:02.331133 32146 hierarchical.cpp:1674] Filtered offer with disk(role1):960; cpus(*):1; mem(*):512; ports(*):[31000-32000] on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:02]W:	 [Step 11/11] I0410 07:11:02.331212 32146 hierarchical.cpp:1488] No resources available to allocate!
[07:11:02]W:	 [Step 11/11] I0410 07:11:02.331248 32146 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:02]W:	 [Step 11/11] I0410 07:11:02.331315 32146 hierarchical.cpp:1139] Performed allocation for 1 agents in 845487ns
[07:11:03]W:	 [Step 11/11] I0410 07:11:03.333051 32144 hierarchical.cpp:1674] Filtered offer with disk(role1):960; cpus(*):1; mem(*):512; ports(*):[31000-32000] on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:03]W:	 [Step 11/11] I0410 07:11:03.333127 32144 hierarchical.cpp:1488] No resources available to allocate!
[07:11:03]W:	 [Step 11/11] I0410 07:11:03.333163 32144 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:03]W:	 [Step 11/11] I0410 07:11:03.333228 32144 hierarchical.cpp:1139] Performed allocation for 1 agents in 803381ns
[07:11:04]W:	 [Step 11/11] I0410 07:11:04.335029 32147 hierarchical.cpp:1674] Filtered offer with disk(role1):960; cpus(*):1; mem(*):512; ports(*):[31000-32000] on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:04]W:	 [Step 11/11] I0410 07:11:04.335103 32147 hierarchical.cpp:1488] No resources available to allocate!
[07:11:04]W:	 [Step 11/11] I0410 07:11:04.335139 32147 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:04]W:	 [Step 11/11] I0410 07:11:04.335206 32147 hierarchical.cpp:1139] Performed allocation for 1 agents in 859999ns
[07:11:05]W:	 [Step 11/11] I0410 07:11:05.336748 32143 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:05]W:	 [Step 11/11] I0410 07:11:05.336850 32143 hierarchical.cpp:1139] Performed allocation for 1 agents in 958629ns
[07:11:05]W:	 [Step 11/11] I0410 07:11:05.337142 32150 master.cpp:5524] Sending 1 offers to framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:05]W:	 [Step 11/11] I0410 07:11:05.337571 32145 sched.cpp:876] Scheduler::resourceOffers took 36529ns
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.108484 32143 linux.cpp:683] Changing the ownership of the persistent volume at '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/volumes/roles/role1/id1' with uid 0 and gid 0
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.113548 32143 linux.cpp:723] Mounting '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/volumes/roles/role1/id1' to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4/path1' for persistent volume disk(role1)[id1:path1]:64 of container 7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.115826 32147 linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWNS
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.120324 32147 containerizer.cpp:1165] Checkpointing executor's forked pid 16620 to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4/pids/forked.pid'
[07:11:06]W:	 [Step 11/11] + /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer mount --help=false --operation=make-rslave --path=/
[07:11:06]W:	 [Step 11/11] + grep -E /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/.+ /proc/self/mountinfo
[07:11:06]W:	 [Step 11/11] + grep -v 7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:06]W:	 [Step 11/11] + cut '-d ' -f5
[07:11:06]W:	 [Step 11/11] + xargs --no-run-if-empty umount -l
[07:11:06]W:	 [Step 11/11] + mount -n --rbind /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/provisioner/containers/7817548e-0ec3-4273-89f6-006f3b27f8f4/backends/copy/rootfses/2d0cdbbf-1df5-48a3-aec2-02272cf1de44 /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4/.rootfs
[07:11:06]W:	 [Step 11/11] + mount -n --rbind /tmp/fWC4sn/dir1 /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4/.rootfs/tmp
[07:11:06]W:	 [Step 11/11] WARNING: Logging before InitGoogleLogging() is written to STDERR
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.271651 16620 process.cpp:985] libprocess is initialized on 172.30.2.121:49875 with 8 worker threads
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.272328 16620 logging.cpp:195] Logging to STDERR
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.274212 16620 exec.cpp:150] Version: 0.29.0
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.285117 16667 exec.cpp:200] Executor started at: executor(1)@172.30.2.121:49875 with pid 16620
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.286861 32150 slave.cpp:2836] Got registration for executor 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 from executor(1)@172.30.2.121:49875
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.287312 32150 slave.cpp:2922] Checkpointing executor pid 'executor(1)@172.30.2.121:49875' to '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4/pids/libprocess.pid'
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.288703 16673 exec.cpp:225] Executor registered on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.289096 32148 slave.cpp:2010] Sending queued task 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' to executor 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 at executor(1)@172.30.2.121:49875
[07:11:06] :	 [Step 11/11] Registered executor on ip-172-30-2-121.mesosphere.io
[07:11:06] :	 [Step 11/11] Starting task faa8593f-f2fa-4dc7-804a-fc6d72d04868
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.290276 16673 exec.cpp:237] Executor::registered took 334438ns
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.290593 16673 exec.cpp:312] Executor asked to run task 'faa8593f-f2fa-4dc7-804a-fc6d72d04868'
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.290724 16673 exec.cpp:321] Executor::launchTask took 110583ns
[07:11:06] :	 [Step 11/11] Forked command at 16676
[07:11:06] :	 [Step 11/11] sh -c 'sleep 1000'
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.295028 16674 exec.cpp:535] Executor sending status update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.295730 32149 slave.cpp:3195] Handling status update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 from executor(1)@172.30.2.121:49875
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.296897 32143 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.296941 32143 status_update_manager.cpp:497] Creating StatusUpdate stream for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.297343 32143 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.337308 32146 hierarchical.cpp:1488] No resources available to allocate!
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.337349 32146 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:06]W:	 [Step 11/11] I0410 07:11:06.337414 32146 hierarchical.cpp:1139] Performed allocation for 1 agents in 268821ns
[07:11:07]W:	 [Step 11/11] I0410 07:11:07.338022 32149 hierarchical.cpp:1488] No resources available to allocate!
[07:11:07]W:	 [Step 11/11] I0410 07:11:07.338086 32149 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:07]W:	 [Step 11/11] I0410 07:11:07.338155 32149 hierarchical.cpp:1139] Performed allocation for 1 agents in 329314ns
[07:11:08]W:	 [Step 11/11] I0410 07:11:08.339215 32145 hierarchical.cpp:1488] No resources available to allocate!
[07:11:08]W:	 [Step 11/11] I0410 07:11:08.339272 32145 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:08]W:	 [Step 11/11] I0410 07:11:08.339334 32145 hierarchical.cpp:1139] Performed allocation for 1 agents in 299436ns
[07:11:09]W:	 [Step 11/11] I0410 07:11:09.339865 32149 hierarchical.cpp:1488] No resources available to allocate!
[07:11:09]W:	 [Step 11/11] I0410 07:11:09.339925 32149 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:09]W:	 [Step 11/11] I0410 07:11:09.339989 32149 hierarchical.cpp:1139] Performed allocation for 1 agents in 303531ns
[07:11:10]W:	 [Step 11/11] I0410 07:11:10.341012 32145 hierarchical.cpp:1488] No resources available to allocate!
[07:11:10]W:	 [Step 11/11] I0410 07:11:10.341078 32145 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:10]W:	 [Step 11/11] I0410 07:11:10.341146 32145 hierarchical.cpp:1139] Performed allocation for 1 agents in 339331ns
[07:11:11]W:	 [Step 11/11] I0410 07:11:11.341923 32149 hierarchical.cpp:1488] No resources available to allocate!
[07:11:11]W:	 [Step 11/11] I0410 07:11:11.341987 32149 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:11]W:	 [Step 11/11] I0410 07:11:11.342056 32149 hierarchical.cpp:1139] Performed allocation for 1 agents in 334175ns
[07:11:12]W:	 [Step 11/11] I0410 07:11:12.342540 32146 hierarchical.cpp:1488] No resources available to allocate!
[07:11:12]W:	 [Step 11/11] I0410 07:11:12.342607 32146 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:12]W:	 [Step 11/11] I0410 07:11:12.342677 32146 hierarchical.cpp:1139] Performed allocation for 1 agents in 366719ns
[07:11:13]W:	 [Step 11/11] I0410 07:11:13.343641 32144 hierarchical.cpp:1488] No resources available to allocate!
[07:11:13]W:	 [Step 11/11] I0410 07:11:13.343708 32144 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:13]W:	 [Step 11/11] I0410 07:11:13.343775 32144 hierarchical.cpp:1139] Performed allocation for 1 agents in 401082ns
[07:11:14]W:	 [Step 11/11] I0410 07:11:14.344359 32147 hierarchical.cpp:1488] No resources available to allocate!
[07:11:14]W:	 [Step 11/11] I0410 07:11:14.344424 32147 hierarchical.cpp:1583] No inverse offers to send out!
[07:11:14]W:	 [Step 11/11] I0410 07:11:14.344511 32147 hierarchical.cpp:1139] Performed allocation for 1 agents in 379136ns
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.075608 32149 slave.cpp:4956] Querying resource estimator for oversubscribable resources
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.075881 32149 slave.cpp:4970] Received oversubscribable resources  from the resource estimator
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.083894 32145 slave.cpp:3675] Received ping from slave-observer(424)@172.30.2.121:48158
[07:11:15] :	 [Step 11/11] ../../src/tests/containerizer/filesystem_isolator_tests.cpp:705: Failure
[07:11:15] :	 [Step 11/11] Failed to wait 15secs for status
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.087579 32145 master.cpp:1275] Framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158 disconnected
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.087613 32145 master.cpp:2658] Disconnecting framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.087642 32145 master.cpp:2682] Deactivating framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.087797 32146 hierarchical.cpp:375] Deactivated framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:15]W:	 [Step 11/11] W0410 07:11:15.088268 32145 master.hpp:1822] Master attempted to send message to disconnected framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.088387 32145 master.cpp:1299] Giving framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158 0ns to failover
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.088562 32144 hierarchical.cpp:891] Recovered disk(role1):960; cpus(*):1; mem(*):512; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(role1):960; ports(*):[31000-32000]; disk(role1)[id1:path1]:64, allocated: disk(role1)[id1:path1]:64; cpus(*):1; mem(*):512) on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 from framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:15] :	 [Step 11/11] ../../src/tests/containerizer/filesystem_isolator_tests.cpp:693: Failure
[07:11:15] :	 [Step 11/11] Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
[07:11:15] :	 [Step 11/11]          Expected: to be called at least once
[07:11:15] :	 [Step 11/11]            Actual: never called - unsatisfied and active
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.088798 32147 master.cpp:5376] Framework failover timeout, removing framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.088825 32147 master.cpp:6109] Removing framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (default) at scheduler-8d7cbfaa-f91a-4416-aa6a-bdf54a973c01@172.30.2.121:48158
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.088986 32148 slave.cpp:2226] Asked to shut down framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 by master@172.30.2.121:48158
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089001 32147 master.cpp:6624] Updating the state of task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089030 32148 slave.cpp:2251] Shutting down framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089051 32146 containerizer.cpp:1439] Destroying container '7817548e-0ec3-4273-89f6-006f3b27f8f4'
[07:11:15] :	 [Step 11/11] Shutting down
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089102 32148 slave.cpp:4409] Shutting down executor 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 at executor(1)@172.30.2.121:49875
[07:11:15] :	 [Step 11/11] Sending SIGTERM to process tree at pid 16676
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089588 32147 master.cpp:6690] Removing task faa8593f-f2fa-4dc7-804a-fc6d72d04868 with resources cpus(*):1; mem(*):512; disk(role1)[id1:path1]:64 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io)
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089685 32150 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):512; disk(role1)[id1:path1]:64 (total: cpus(*):2; mem(*):1024; disk(role1):960; ports(*):[31000-32000]; disk(role1)[id1:path1]:64, allocated: ) on agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 from framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089767 16669 exec.cpp:399] Executor asked to shutdown
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089890 16669 exec.cpp:414] Executor::shutdown took 13868ns
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.089915 16671 exec.cpp:91] Scheduling shutdown of the executor in 5secs
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.090278 32149 hierarchical.cpp:326] Removed framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.092268 32147 cgroups.cpp:2676] Freezing cgroup /sys/fs/cgroup/freezer/mesos/7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.094388 32150 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/7817548e-0ec3-4273-89f6-006f3b27f8f4 after 2.07488ms
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.096920 32147 cgroups.cpp:2694] Thawing cgroup /sys/fs/cgroup/freezer/mesos/7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.099067 32150 cgroups.cpp:1438] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos/7817548e-0ec3-4273-89f6-006f3b27f8f4 after 2.103808ms
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.113828 32147 slave.cpp:3721] executor(1)@172.30.2.121:49875 exited
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.146421 32148 containerizer.cpp:1674] Executor for container '7817548e-0ec3-4273-89f6-006f3b27f8f4' has exited
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.149034 32150 linux.cpp:798] Unmounting volume '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4/path1' for container 7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.149090 32150 linux.cpp:814] Ignoring unmounting sandbox/work directory for container 7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.149559 32146 provisioner.cpp:330] Destroying container rootfs at '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/provisioner/containers/7817548e-0ec3-4273-89f6-006f3b27f8f4/backends/copy/rootfses/2d0cdbbf-1df5-48a3-aec2-02272cf1de44' for container 7817548e-0ec3-4273-89f6-006f3b27f8f4
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.345477 32148 hierarchical.cpp:1488] No resources available to allocate!
[07:11:15]W:	 [Step 11/11] I0410 07:11:15.345577 32148 hierarchical.cpp:1139] Performed allocation for 1 agents in 322403ns
[07:11:16]W:	 [Step 11/11] I0410 07:11:16.346096 32147 hierarchical.cpp:1488] No resources available to allocate!
[07:11:16]W:	 [Step 11/11] I0410 07:11:16.346191 32147 hierarchical.cpp:1139] Performed allocation for 1 agents in 286270ns
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.346915 32146 hierarchical.cpp:1488] No resources available to allocate!
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.347010 32146 hierarchical.cpp:1139] Performed allocation for 1 agents in 298313ns
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.809588 32143 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 to the agent
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.809937 32145 slave.cpp:3593] Forwarding the update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 to master@172.30.2.121:48158
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.810128 32145 slave.cpp:3487] Status update manager successfully handled status update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.810178 32145 slave.cpp:3503] Sending acknowledgement for status update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 to executor(1)@172.30.2.121:49875
[07:11:17]W:	 [Step 11/11] W0410 07:11:17.810344 32146 master.cpp:4956] Ignoring status update TASK_RUNNING (UUID: f44cb61d-1363-4a9b-9b15-cb89eb0e56f5) for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 from agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io) because the framework is unknown
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.810583 32145 poll_socket.cpp:131] Socket error while connecting
[07:11:17]W:	 [Step 11/11] I0410 07:11:17.810647 32145 process.cpp:1649] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.121:49875', connect: Socket error while connecting
[07:11:17]W:	 [Step 11/11] E0410 07:11:17.810726 32145 process.cpp:1957] Failed to shutdown socket with fd 89: Transport endpoint is not connected
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.059679 32150 slave.cpp:4097] Executor 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 terminated with signal Killed
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.059758 32150 slave.cpp:4201] Cleaning up executor 'faa8593f-f2fa-4dc7-804a-fc6d72d04868' of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000 at executor(1)@172.30.2.121:49875
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060102 32147 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4' for gc 6.99999930555556days in the future
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060282 32147 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868' for gc 6.99999930403852days in the future
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060376 32150 slave.cpp:4289] Cleaning up framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060392 32147 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868/runs/7817548e-0ec3-4273-89f6-006f3b27f8f4' for gc 6.99999930313778days in the future
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060477 32147 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000/executors/faa8593f-f2fa-4dc7-804a-fc6d72d04868' for gc 6.99999930202667days in the future
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060586 32143 status_update_manager.cpp:282] Closing status update streams for framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060614 32146 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000' for gc 6.99999929929481days in the future
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060649 32143 status_update_manager.cpp:528] Cleaning up status update stream for task faa8593f-f2fa-4dc7-804a-fc6d72d04868 of framework 57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060667 32150 slave.cpp:811] Agent terminating
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060768 32146 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_RecoverOrphanedPersistentVolume_YiwiGP/meta/slaves/57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0/frameworks/57a2cf4e-da76-4801-a887-c0c84ad59d0d-0000' for gc 6.99999929850667days in the future
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060894 32144 master.cpp:1236] Agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io) disconnected
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060917 32144 master.cpp:2717] Disconnecting agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io)
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.060997 32144 master.cpp:2736] Deactivating agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 at slave(456)@172.30.2.121:48158 (ip-172-30-2-121.mesosphere.io)
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.061138 32148 hierarchical.cpp:560] Agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0 deactivated
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.347623 32147 hierarchical.cpp:1488] No resources available to allocate!
[07:11:18]W:	 [Step 11/11] I0410 07:11:18.347723 32147 hierarchical.cpp:1139] Performed allocation for 1 agents in 238267ns
[07:11:19]W:	 [Step 11/11] I0410 07:11:19.348975 32143 hierarchical.cpp:1488] No resources available to allocate!
[07:11:19]W:	 [Step 11/11] I0410 07:11:19.349076 32143 hierarchical.cpp:1139] Performed allocation for 1 agents in 253755ns
[07:11:19]W:	 [Step 11/11] I0410 07:11:19.492455 32149 master.cpp:1089] Master terminating
[07:11:19]W:	 [Step 11/11] I0410 07:11:19.493062 32148 hierarchical.cpp:505] Removed agent 57a2cf4e-da76-4801-a887-c0c84ad59d0d-S0
[07:11:19] :	 [Step 11/11] ../../3rdparty/libprocess/include/process/gmock.hpp:487: Failure
[07:11:19] :	 [Step 11/11] Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A()))...
[07:11:19] :	 [Step 11/11]     Expected args: dispatch matcher (1-byte object , 16-byte object )
[07:11:19] :	 [Step 11/11]          Expected: to be called once
[07:11:19] :	 [Step 11/11]            Actual: never called - unsatisfied and active
[07:11:19] :	 [Step 11/11] [  FAILED  ] LinuxFilesystemIsolatorTest.ROOT_RecoverOrphanedPersistentVolume (21216 ms)

Attachments

Issue Links

is related to

MESOS-4943 Reduce the size of LinuxRootfs in tests.

Resolved

Activity

People

Assignee:: Gilbert Song

Reporter:: Greg Mann

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 11/Apr/16 20:14

Updated:: 26/Apr/17 17:01

Resolved:: 23/Jun/16 16:05