Greg Mann created MESOS-5176:
--------------------------------
Summary:
LinuxFilesystemIsolatorTest.ROOT_RecoverOrphanedPersistentVolume is flaky
Key: MESOS-5176
URL: https://issues.apache.org/jira/browse/MESOS-5176
Project: Mesos
Issue Type: Bug
Components: tests
Environment: CentOS 7, with libevent and SSL enabled
Reporter: Greg Mann
Observed on the internal Mesosphere CI:
{code}
[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 [email protected]: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 [email protected]:48158
[07:11:00]W: [Step 11/11] I0410 07:11:00.068964 32143 sched.cpp:384]
Authenticating with master [email protected]: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 [email protected]: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
[email protected]: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 [email protected]:48158
[07:11:00]W: [Step 11/11] I0410 07:11:00.071231 32147 sched.cpp:779]
Sending SUBSCRIBE call to [email protected]: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
[email protected]: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 [email protected]:48158
[07:11:00]W: [Step 11/11] I0410 07:11:00.074878 32148 slave.cpp:1002]
Authenticating with master [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
'[email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
