Jie Yu created MESOS-4208:
-----------------------------
Summary: PersistentVolumeTest.BadACLDropCreateAndDestroy is flaky
Key: MESOS-4208
URL: https://issues.apache.org/jira/browse/MESOS-4208
Project: Mesos
Issue Type: Bug
Reporter: Jie Yu
{noformat}
[ RUN ] PersistentVolumeTest.BadACLDropCreateAndDestroy
I1219 09:51:32.623245 31878 leveldb.cpp:174] Opened db in 4.393596ms
I1219 09:51:32.624084 31878 leveldb.cpp:181] Compacted db in 709447ns
I1219 09:51:32.624186 31878 leveldb.cpp:196] Created db iterator in 21252ns
I1219 09:51:32.624290 31878 leveldb.cpp:202] Seeked to beginning of db in
11391ns
I1219 09:51:32.624378 31878 leveldb.cpp:271] Iterated through 0 keys in the db
in 611ns
I1219 09:51:32.624505 31878 replica.cpp:779] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I1219 09:51:32.625195 31904 recover.cpp:447] Starting replica recovery
I1219 09:51:32.625641 31904 recover.cpp:473] Replica is in EMPTY status
I1219 09:51:32.627305 31904 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from (6740)@172.17.0.3:36408
I1219 09:51:32.627749 31904 recover.cpp:193] Received a recover response from a
replica in EMPTY status
I1219 09:51:32.628330 31904 recover.cpp:564] Updating replica status to STARTING
I1219 09:51:32.629068 31906 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 410494ns
I1219 09:51:32.629169 31906 replica.cpp:320] Persisted replica status to
STARTING
I1219 09:51:32.629598 31906 recover.cpp:473] Replica is in STARTING status
I1219 09:51:32.630782 31912 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from (6741)@172.17.0.3:36408
I1219 09:51:32.631166 31901 recover.cpp:193] Received a recover response from a
replica in STARTING status
I1219 09:51:32.632467 31902 recover.cpp:564] Updating replica status to VOTING
I1219 09:51:32.633600 31907 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 311370ns
I1219 09:51:32.633627 31907 replica.cpp:320] Persisted replica status to VOTING
I1219 09:51:32.633719 31907 recover.cpp:578] Successfully joined the Paxos group
I1219 09:51:32.633874 31907 recover.cpp:462] Recover process terminated
I1219 09:51:32.636409 31909 master.cpp:365] Master
bded856d-1c7f-4fad-a8bc-3629ba8c59d3 (60ab6e727501) started on 172.17.0.3:36408
I1219 09:51:32.636593 31909 master.cpp:367] Flags at startup:
--acls="create_volumes {
principals {
values: "creator-principal"
}
volume_types {
type: ANY
}
}
create_volumes {
principals {
type: ANY
}
volume_types {
type: NONE
}
}
" --allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate="false" --authenticate_slaves="true" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/SpPF7B/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5"
--quiet="false" --recovery_slave_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="25secs" --registry_strict="true" --roles="role1"
--root_submissions="true" --slave_ping_timeout="15secs"
--slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
--webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui"
--work_dir="/tmp/SpPF7B/master" --zk_session_timeout="10secs"
I1219 09:51:32.637055 31909 master.cpp:414] Master allowing unauthenticated
frameworks to register
I1219 09:51:32.637068 31909 master.cpp:417] Master only allowing authenticated
slaves to register
I1219 09:51:32.637094 31909 credentials.hpp:35] Loading credentials for
authentication from '/tmp/SpPF7B/credentials'
I1219 09:51:32.637403 31909 master.cpp:456] Using default 'crammd5'
authenticator
I1219 09:51:32.637555 31909 master.cpp:493] Authorization enabled
W1219 09:51:32.637575 31909 master.cpp:553] The '--roles' flag is deprecated.
This flag will be removed in the future. See the Mesos 0.27 upgrade notes for
more information
I1219 09:51:32.637806 31897 whitelist_watcher.cpp:77] No whitelist given
I1219 09:51:32.637820 31910 hierarchical.cpp:147] Initialized hierarchical
allocator process
I1219 09:51:32.639677 31909 master.cpp:1629] The newly elected leader is
[email protected]:36408 with id bded856d-1c7f-4fad-a8bc-3629ba8c59d3
I1219 09:51:32.639768 31909 master.cpp:1642] Elected as the leading master!
I1219 09:51:32.639892 31909 master.cpp:1387] Recovering from registrar
I1219 09:51:32.640136 31907 registrar.cpp:307] Recovering registrar
I1219 09:51:32.640929 31901 log.cpp:659] Attempting to start the writer
I1219 09:51:32.642199 31912 replica.cpp:493] Replica received implicit promise
request from (6742)@172.17.0.3:36408 with proposal 1
I1219 09:51:32.642719 31912 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 445876ns
I1219 09:51:32.642755 31912 replica.cpp:342] Persisted promised to 1
I1219 09:51:32.643478 31904 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I1219 09:51:32.645009 31909 replica.cpp:388] Replica received explicit promise
request from (6743)@172.17.0.3:36408 for position 0 with proposal 2
I1219 09:51:32.645356 31909 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 310064ns
I1219 09:51:32.645382 31909 replica.cpp:712] Persisted action at 0
I1219 09:51:32.646662 31909 replica.cpp:537] Replica received write request for
position 0 from (6744)@172.17.0.3:36408
I1219 09:51:32.646721 31909 leveldb.cpp:436] Reading position from leveldb took
29298ns
I1219 09:51:32.647047 31909 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 283424ns
I1219 09:51:32.647073 31909 replica.cpp:712] Persisted action at 0
I1219 09:51:32.647722 31909 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I1219 09:51:32.648052 31909 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 300825ns
I1219 09:51:32.648077 31909 replica.cpp:712] Persisted action at 0
I1219 09:51:32.648095 31909 replica.cpp:697] Replica learned NOP action at
position 0
I1219 09:51:32.655295 31899 log.cpp:675] Writer started with ending position 0
I1219 09:51:32.656543 31905 leveldb.cpp:436] Reading position from leveldb took
32788ns
I1219 09:51:32.658164 31905 registrar.cpp:340] Successfully fetched the
registry (0B) in 0ns
I1219 09:51:32.658604 31905 registrar.cpp:439] Applied 1 operations in 38183ns;
attempting to update the 'registry'
I1219 09:51:32.660102 31905 log.cpp:683] Attempting to append 170 bytes to the
log
I1219 09:51:32.660538 31906 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I1219 09:51:32.661872 31906 replica.cpp:537] Replica received write request for
position 1 from (6745)@172.17.0.3:36408
I1219 09:51:32.662719 31906 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 483018ns
I1219 09:51:32.663054 31906 replica.cpp:712] Persisted action at 1
I1219 09:51:32.664008 31902 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I1219 09:51:32.664330 31902 leveldb.cpp:341] Persisting action (191 bytes) to
leveldb took 287310ns
I1219 09:51:32.664355 31902 replica.cpp:712] Persisted action at 1
I1219 09:51:32.664376 31902 replica.cpp:697] Replica learned APPEND action at
position 1
I1219 09:51:32.665365 31902 registrar.cpp:484] Successfully updated the
'registry' in 0ns
I1219 09:51:32.665493 31902 registrar.cpp:370] Successfully recovered registrar
I1219 09:51:32.665894 31902 master.cpp:1439] Recovered 0 slaves from the
Registry (131B) ; allowing 10mins for slaves to re-register
I1219 09:51:32.665990 31902 hierarchical.cpp:165] Skipping recovery of
hierarchical allocator: nothing to recover
I1219 09:51:32.666266 31902 log.cpp:702] Attempting to truncate the log to 1
I1219 09:51:32.666424 31902 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I1219 09:51:32.667181 31907 replica.cpp:537] Replica received write request for
position 2 from (6746)@172.17.0.3:36408
I1219 09:51:32.667768 31907 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 335947ns
I1219 09:51:32.668067 31907 replica.cpp:712] Persisted action at 2
I1219 09:51:32.668942 31906 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I1219 09:51:32.669240 31906 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 266566ns
I1219 09:51:32.669292 31906 leveldb.cpp:399] Deleting ~1 keys from leveldb took
27852ns
I1219 09:51:32.669314 31906 replica.cpp:712] Persisted action at 2
I1219 09:51:32.669334 31906 replica.cpp:697] Replica learned TRUNCATE action at
position 2
I1219 09:51:32.691251 31878 containerizer.cpp:141] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W1219 09:51:32.691759 31878 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
I1219 09:51:32.697428 31901 slave.cpp:191] Slave started on
228)@172.17.0.3:36408
I1219 09:51:32.697459 31901 slave.cpp:192] Flags at startup:
--appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
--cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
--cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
--cgroups_root="mesos" --container_disk_watch_interval="15secs"
--containerizers="mesos"
--credential="/tmp/PersistentVolumeTest_BadACLDropCreateAndDestroy_gWLtnc/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="auth.docker.io" --docker_auth_server_port="443"
--docker_kill_orphans="true"
--docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local"
--docker_puller_timeout="60" --docker_registry="registry-1.docker.io"
--docker_registry_port="443" --docker_remove_delay="6hrs"
--docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
--docker_store_dir="/tmp/mesos/store/docker"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/PersistentVolumeTest_BadACLDropCreateAndDestroy_gWLtnc/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --image_provisioner_backend="copy"
--initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
--launcher_dir="/mesos/mesos-0.27.0/_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):2048"
--revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
--strict="true" --switch_user="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/PersistentVolumeTest_BadACLDropCreateAndDestroy_gWLtnc"
I1219 09:51:32.697963 31901 credentials.hpp:83] Loading credential for
authentication from
'/tmp/PersistentVolumeTest_BadACLDropCreateAndDestroy_gWLtnc/credential'
I1219 09:51:32.698210 31901 slave.cpp:322] Slave using credential for:
test-principal
I1219 09:51:32.698449 31901 resources.cpp:478] Parsing resources as JSON
failed: cpus:2;mem:1024;disk(role1):2048
Trying semicolon-delimited string format instead
I1219 09:51:32.699065 31901 slave.cpp:392] Slave resources: cpus(*):2;
mem(*):1024; disk(role1):2048; ports(*):[31000-32000]
I1219 09:51:32.699137 31901 slave.cpp:400] Slave attributes: [ ]
I1219 09:51:32.699151 31901 slave.cpp:405] Slave hostname: 60ab6e727501
I1219 09:51:32.699161 31901 slave.cpp:410] Slave checkpoint: true
I1219 09:51:32.699364 31878 sched.cpp:164] Version: 0.27.0
I1219 09:51:32.700614 31911 sched.cpp:262] New master detected at
[email protected]:36408
I1219 09:51:32.700703 31911 sched.cpp:272] No credentials provided. Attempting
to register without authentication
I1219 09:51:32.700724 31911 sched.cpp:714] Sending SUBSCRIBE call to
[email protected]:36408
I1219 09:51:32.700839 31911 sched.cpp:747] Will retry registration in
620.399428ms if necessary
I1219 09:51:32.701244 31903 master.cpp:2197] Received SUBSCRIBE call for
framework 'default' at
[email protected]:36408
I1219 09:51:32.701313 31903 master.cpp:1668] Authorizing framework principal
'test-principal' to receive offers for role 'role1'
I1219 09:51:32.701625 31903 master.cpp:2268] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I1219 09:51:32.702308 31903 hierarchical.cpp:260] Added framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:32.702386 31903 hierarchical.cpp:1329] No resources available to
allocate!
I1219 09:51:32.702422 31903 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.702448 31903 hierarchical.cpp:1079] Performed allocation for 0
slaves in 114358ns
I1219 09:51:32.702638 31903 sched.cpp:641] Framework registered with
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:32.702688 31903 sched.cpp:655] Scheduler::registered took 25558ns
I1219 09:51:32.703553 31901 state.cpp:58] Recovering state from
'/tmp/PersistentVolumeTest_BadACLDropCreateAndDestroy_gWLtnc/meta'
I1219 09:51:32.704118 31897 status_update_manager.cpp:200] Recovering status
update manager
I1219 09:51:32.704407 31907 containerizer.cpp:383] Recovering containerizer
I1219 09:51:32.705373 31907 slave.cpp:4427] Finished recovery
I1219 09:51:32.705991 31907 slave.cpp:4599] Querying resource estimator for
oversubscribable resources
I1219 09:51:32.706277 31907 slave.cpp:4613] Received oversubscribable resources
from the resource estimator
I1219 09:51:32.706666 31907 slave.cpp:729] New master detected at
[email protected]:36408
I1219 09:51:32.706738 31907 slave.cpp:792] Authenticating with master
[email protected]:36408
I1219 09:51:32.706760 31907 slave.cpp:797] Using default CRAM-MD5 authenticatee
I1219 09:51:32.706886 31899 status_update_manager.cpp:174] Pausing sending
status updates
I1219 09:51:32.706941 31907 slave.cpp:765] Detecting new master
I1219 09:51:32.707036 31899 authenticatee.cpp:121] Creating new client SASL
connection
I1219 09:51:32.707291 31910 master.cpp:5423] Authenticating
slave(228)@172.17.0.3:36408
I1219 09:51:32.707479 31910 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(510)@172.17.0.3:36408
I1219 09:51:32.707849 31910 authenticator.cpp:98] Creating new server SASL
connection
I1219 09:51:32.708082 31910 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I1219 09:51:32.708112 31910 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1219 09:51:32.708196 31910 authenticator.cpp:203] Received SASL authentication
start
I1219 09:51:32.708395 31910 authenticator.cpp:325] Authentication requires more
steps
I1219 09:51:32.708611 31902 authenticatee.cpp:258] Received SASL authentication
step
I1219 09:51:32.708773 31910 authenticator.cpp:231] Received SASL authentication
step
I1219 09:51:32.708889 31910 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '60ab6e727501' server FQDN: '60ab6e727501'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1219 09:51:32.708976 31910 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I1219 09:51:32.709096 31910 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1219 09:51:32.709200 31910 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '60ab6e727501' server FQDN: '60ab6e727501'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1219 09:51:32.709285 31910 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1219 09:51:32.709363 31910 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1219 09:51:32.709452 31910 authenticator.cpp:317] Authentication success
I1219 09:51:32.709707 31910 authenticatee.cpp:298] Authentication success
I1219 09:51:32.710252 31910 slave.cpp:860] Successfully authenticated with
master [email protected]:36408
I1219 09:51:32.710525 31910 slave.cpp:1254] Will retry registration in
17.44437ms if necessary
I1219 09:51:32.709839 31908 master.cpp:5453] Successfully authenticated
principal 'test-principal' at slave(228)@172.17.0.3:36408
I1219 09:51:32.710985 31908 master.cpp:4132] Registering slave at
slave(228)@172.17.0.3:36408 (60ab6e727501) with id
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0
I1219 09:51:32.711645 31908 registrar.cpp:439] Applied 1 operations in 83191ns;
attempting to update the 'registry'
I1219 09:51:32.709908 31912 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(510)@172.17.0.3:36408
I1219 09:51:32.713407 31908 log.cpp:683] Attempting to append 343 bytes to the
log
I1219 09:51:32.713646 31912 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I1219 09:51:32.714884 31911 replica.cpp:537] Replica received write request for
position 3 from (6758)@172.17.0.3:36408
I1219 09:51:32.715221 31911 leveldb.cpp:341] Persisting action (362 bytes) to
leveldb took 288909ns
I1219 09:51:32.715250 31911 replica.cpp:712] Persisted action at 3
I1219 09:51:32.716145 31912 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I1219 09:51:32.716689 31912 leveldb.cpp:341] Persisting action (364 bytes) to
leveldb took 512217ns
I1219 09:51:32.716716 31912 replica.cpp:712] Persisted action at 3
I1219 09:51:32.716737 31912 replica.cpp:697] Replica learned APPEND action at
position 3
I1219 09:51:32.718426 31911 registrar.cpp:484] Successfully updated the
'registry' in 0ns
I1219 09:51:32.719441 31902 slave.cpp:3371] Received ping from
slave-observer(228)@172.17.0.3:36408
I1219 09:51:32.719843 31909 log.cpp:702] Attempting to truncate the log to 3
I1219 09:51:32.719908 31911 master.cpp:4200] Registered slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 at slave(228)@172.17.0.3:36408
(60ab6e727501) with cpus(*):2; mem(*):1024; disk(role1):2048;
ports(*):[31000-32000]
I1219 09:51:32.720064 31911 slave.cpp:904] Registered with master
[email protected]:36408; given slave ID bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0
I1219 09:51:32.720088 31911 fetcher.cpp:81] Clearing fetcher cache
I1219 09:51:32.720491 31911 slave.cpp:927] Checkpointing SlaveInfo to
'/tmp/PersistentVolumeTest_BadACLDropCreateAndDestroy_gWLtnc/meta/slaves/bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0/slave.info'
I1219 09:51:32.720844 31909 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I1219 09:51:32.720929 31911 slave.cpp:963] Forwarding total oversubscribed
resources
I1219 09:51:32.721017 31903 status_update_manager.cpp:181] Resuming sending
status updates
I1219 09:51:32.721099 31911 master.cpp:4542] Received update of slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 at slave(228)@172.17.0.3:36408
(60ab6e727501) with total oversubscribed resources
I1219 09:51:32.721141 31905 hierarchical.cpp:465] Added slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 (60ab6e727501) with cpus(*):2;
mem(*):1024; disk(role1):2048; ports(*):[31000-32000] (allocated: )
I1219 09:51:32.721879 31911 replica.cpp:537] Replica received write request for
position 4 from (6759)@172.17.0.3:36408
I1219 09:51:32.722293 31905 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.722337 31905 hierarchical.cpp:1101] Performed allocation for
slave bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 in 1.155563ms
I1219 09:51:32.722681 31905 hierarchical.cpp:521] Slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 (60ab6e727501) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(role1):2048;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
ports(*):[31000-32000]; disk(role1):2048)
I1219 09:51:32.722713 31909 master.cpp:5252] Sending 1 offers to framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:32.723031 31905 hierarchical.cpp:1329] No resources available to
allocate!
I1219 09:51:32.723073 31905 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.723095 31905 hierarchical.cpp:1101] Performed allocation for
slave bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 in 368889ns
I1219 09:51:32.723191 31909 sched.cpp:811] Scheduler::resourceOffers took
113921ns
I1219 09:51:32.723410 31911 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 1.418243ms
I1219 09:51:32.723497 31911 replica.cpp:712] Persisted action at 4
I1219 09:51:32.724326 31907 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I1219 09:51:32.724758 31907 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 329678ns
I1219 09:51:32.724917 31907 leveldb.cpp:399] Deleting ~2 keys from leveldb took
58317ns
I1219 09:51:32.725025 31907 replica.cpp:712] Persisted action at 4
I1219 09:51:32.725127 31907 replica.cpp:697] Replica learned TRUNCATE action at
position 4
I1219 09:51:32.731515 31910 hierarchical.cpp:1329] No resources available to
allocate!
I1219 09:51:32.731564 31910 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.731591 31910 hierarchical.cpp:1079] Performed allocation for 1
slaves in 239271ns
I1219 09:51:32.741710 31910 master.cpp:3055] Processing ACCEPT call for offers:
[ bded856d-1c7f-4fad-a8bc-3629ba8c59d3-O0 ] on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 at slave(228)@172.17.0.3:36408
(60ab6e727501) for framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
(default) at [email protected]:36408
I1219 09:51:32.741770 31910 master.cpp:2843] Authorizing principal
'test-principal' to create volumes
E1219 09:51:32.742707 31910 master.cpp:1737] Dropping CREATE offer operation
from framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408: Not authorized
to create persistent volumes as 'test-principal'
I1219 09:51:32.743219 31910 hierarchical.cpp:880] Recovered cpus(*):2;
mem(*):1024; ports(*):[31000-32000]; disk(role1):2048 (total: cpus(*):2;
mem(*):1024; disk(role1):2048; ports(*):[31000-32000], allocated: ) on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 from framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:32.752542 31908 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.752590 31908 hierarchical.cpp:1079] Performed allocation for 1
slaves in 888401ns
I1219 09:51:32.753018 31908 master.cpp:5252] Sending 1 offers to framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:32.753435 31908 sched.cpp:811] Scheduler::resourceOffers took
92252ns
I1219 09:51:32.761533 31878 sched.cpp:164] Version: 0.27.0
I1219 09:51:32.761931 31897 master.cpp:3570] Processing DECLINE call for
offers: [ bded856d-1c7f-4fad-a8bc-3629ba8c59d3-O1 ] for framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:32.762373 31897 sched.cpp:262] New master detected at
[email protected]:36408
I1219 09:51:32.762451 31897 sched.cpp:272] No credentials provided. Attempting
to register without authentication
I1219 09:51:32.762470 31897 sched.cpp:714] Sending SUBSCRIBE call to
[email protected]:36408
I1219 09:51:32.762543 31897 sched.cpp:747] Will retry registration in
465.481193ms if necessary
I1219 09:51:32.762572 31898 hierarchical.cpp:880] Recovered cpus(*):2;
mem(*):1024; ports(*):[31000-32000]; disk(role1):2048 (total: cpus(*):2;
mem(*):1024; disk(role1):2048; ports(*):[31000-32000], allocated: ) on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 from framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:32.762722 31898 master.cpp:2197] Received SUBSCRIBE call for
framework 'creator-framework' at
[email protected]:36408
I1219 09:51:32.762785 31898 master.cpp:1668] Authorizing framework principal
'creator-principal' to receive offers for role 'role1'
I1219 09:51:32.763036 31897 master.cpp:2268] Subscribing framework
creator-framework with checkpointing disabled and capabilities [ ]
I1219 09:51:32.763464 31898 hierarchical.cpp:260] Added framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:32.763562 31897 sched.cpp:641] Framework registered with
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:32.763605 31897 sched.cpp:655] Scheduler::registered took 20669ns
I1219 09:51:32.763804 31908 master.cpp:2650] Processing SUPPRESS call for
framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:32.764343 31898 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.764382 31898 hierarchical.cpp:1079] Performed allocation for 1
slaves in 893765ns
I1219 09:51:32.764428 31898 hierarchical.cpp:953] Suppressed offers for
framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:32.764746 31898 master.cpp:5252] Sending 1 offers to framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408
I1219 09:51:32.765127 31898 sched.cpp:811] Scheduler::resourceOffers took
83608ns
I1219 09:51:32.773298 31900 hierarchical.cpp:1329] No resources available to
allocate!
I1219 09:51:32.773339 31900 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.773365 31900 hierarchical.cpp:1079] Performed allocation for 1
slaves in 201759ns
I1219 09:51:32.782901 31898 master.cpp:3055] Processing ACCEPT call for offers:
[ bded856d-1c7f-4fad-a8bc-3629ba8c59d3-O2 ] on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 at slave(228)@172.17.0.3:36408
(60ab6e727501) for framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
(creator-framework) at
[email protected]:36408
I1219 09:51:32.782961 31898 master.cpp:2843] Authorizing principal
'creator-principal' to create volumes
I1219 09:51:32.784190 31904 master.cpp:3362] Applying CREATE operation for
volumes disk(role1)[id1:path1]:128 from framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408 to slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 at slave(228)@172.17.0.3:36408
(60ab6e727501)
I1219 09:51:32.784548 31904 master.cpp:6486] Sending checkpointed resources
disk(role1)[id1:path1]:128 to slave bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 at
slave(228)@172.17.0.3:36408 (60ab6e727501)
I1219 09:51:32.786471 31904 hierarchical.cpp:642] Updated allocation of
framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 from cpus(*):2; mem(*):1024;
ports(*):[31000-32000]; disk(role1):2048 to cpus(*):2; mem(*):1024;
ports(*):[31000-32000]; disk(role1):1920; disk(role1)[id1:path1]:128
I1219 09:51:32.786929 31904 hierarchical.cpp:880] Recovered cpus(*):2;
mem(*):1024; ports(*):[31000-32000]; disk(role1):1920;
disk(role1)[id1:path1]:128 (total: cpus(*):2; mem(*):1024; disk(role1):1920;
ports(*):[31000-32000]; disk(role1)[id1:path1]:128, allocated: ) on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 from framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:32.788035 31904 slave.cpp:2277] Updated checkpointed resources from
to disk(role1)[id1:path1]:128
I1219 09:51:32.795177 31902 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.795250 31902 hierarchical.cpp:1079] Performed allocation for 1
slaves in 1.357898ms
I1219 09:51:32.795897 31902 master.cpp:5252] Sending 1 offers to framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408
I1219 09:51:32.796540 31897 sched.cpp:811] Scheduler::resourceOffers took
138880ns
I1219 09:51:32.803026 31902 master.cpp:3570] Processing DECLINE call for
offers: [ bded856d-1c7f-4fad-a8bc-3629ba8c59d3-O3 ] for framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408
I1219 09:51:32.804143 31902 hierarchical.cpp:880] Recovered cpus(*):2;
mem(*):1024; ports(*):[31000-32000]; disk(role1):1920;
disk(role1)[id1:path1]:128 (total: cpus(*):2; mem(*):1024; disk(role1):1920;
ports(*):[31000-32000]; disk(role1)[id1:path1]:128, allocated: ) on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 from framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:32.804622 31907 master.cpp:2650] Processing SUPPRESS call for
framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408
I1219 09:51:32.804729 31907 hierarchical.cpp:953] Suppressed offers for
framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:32.805140 31897 master.cpp:3649] Processing REVIVE call for
framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:32.805250 31897 hierarchical.cpp:973] Removed offer filters for
framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:32.806507 31897 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.806562 31897 hierarchical.cpp:1079] Performed allocation for 1
slaves in 1.284779ms
I1219 09:51:32.807067 31897 master.cpp:5252] Sending 1 offers to framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
../../src/tests/persistent_volume_tests.cpp:1336: Failure
Mock function called more times than expected - returning directly.
Function call: resourceOffers(0x7ffff9edb3a0, @0x7f71079798f0 { 144-byte
object <F0-1B 42-14 71-7F 00-00 00-00 00-00 00-00 00-00 D0-96 02-F0 70-7F 00-00
50-97 02-F0 70-7F 00-00 20-A1 02-F0 70-7F 00-00 50-E0 01-F0 70-7F 00-00 B0-9F
02-F0 70-7F 00-00 00-32 01-F0 70-7F 00-00 ... 00-00 00-00 00-00 00-00 00-00
00-00 00-00 00-00 00-00 00-00 70-7F 00-00 00-00 00-00 00-00 00-00 00-00 00-00
00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 1F-00
00-00> })
Expected: to be called once
Actual: called twice - over-saturated and active
I1219 09:51:32.807899 31897 sched.cpp:811] Scheduler::resourceOffers took
406435ns
I1219 09:51:32.820523 31909 hierarchical.cpp:1329] No resources available to
allocate!
I1219 09:51:32.820611 31909 hierarchical.cpp:1423] No inverse offers to send
out!
I1219 09:51:32.820642 31909 hierarchical.cpp:1079] Performed allocation for 1
slaves in 448034ns
2015-12-19
09:51:33,146:31878(0x7f6ff6ffd700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:39991] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
2015-12-19
09:51:36,482:31878(0x7f6ff6ffd700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:39991] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
2015-12-19
09:51:39,818:31878(0x7f6ff6ffd700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:39991] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
2015-12-19
09:51:43,155:31878(0x7f6ff6ffd700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:39991] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
2015-12-19
09:51:46,490:31878(0x7f6ff6ffd700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:39991] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
../../src/tests/persistent_volume_tests.cpp:1411: Failure
Failed to wait 15secs for offers
I1219 09:51:47.829073 31909 master.cpp:1130] Framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408 disconnected
I1219 09:51:47.829169 31909 master.cpp:2493] Disconnecting framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408
I1219 09:51:47.829200 31909 master.cpp:2517] Deactivating framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408
I1219 09:51:47.829366 31909 master.cpp:1154] Giving framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408 0ns to failover
I1219 09:51:47.829720 31909 hierarchical.cpp:366] Deactivated framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:47.831614 31907 master.cpp:5100] Framework failover timeout,
removing framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
(creator-framework) at
[email protected]:36408
I1219 09:51:47.831748 31907 master.cpp:5835] Removing framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at
[email protected]:36408
I1219 09:51:47.833314 31897 slave.cpp:2012] Asked to shut down framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 by [email protected]:36408
W1219 09:51:47.833421 31897 slave.cpp:2027] Cannot shut down unknown framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:47.834002 31897 hierarchical.cpp:321] Removed framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001
I1219 09:51:47.843332 31908 master.cpp:1130] Framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408 disconnected
I1219 09:51:47.843521 31908 master.cpp:2493] Disconnecting framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:47.843663 31908 master.cpp:2517] Deactivating framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
W1219 09:51:47.844665 31908 master.hpp:1758] Master attempted to send message
to disconnected framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default)
at [email protected]:36408
I1219 09:51:47.845077 31908 master.cpp:1154] Giving framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408 0ns to failover
I1219 09:51:47.844887 31903 hierarchical.cpp:366] Deactivated framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:47.845728 31903 hierarchical.cpp:880] Recovered cpus(*):2;
mem(*):1024; ports(*):[31000-32000]; disk(role1):1920;
disk(role1)[id1:path1]:128 (total: cpus(*):2; mem(*):1024; disk(role1):1920;
ports(*):[31000-32000]; disk(role1)[id1:path1]:128, allocated: ) on slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0 from framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
../../src/tests/persistent_volume_tests.cpp:1404: Failure
Actual function call count doesn't match EXPECT_CALL(sched1,
resourceOffers(&driver1, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I1219 09:51:47.847968 31902 master.cpp:5100] Framework failover timeout,
removing framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:47.848068 31902 master.cpp:5835] Removing framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at
[email protected]:36408
I1219 09:51:47.848553 31902 slave.cpp:2012] Asked to shut down framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 by [email protected]:36408
W1219 09:51:47.848644 31902 slave.cpp:2027] Cannot shut down unknown framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:47.848999 31902 hierarchical.cpp:321] Removed framework
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000
I1219 09:51:47.849782 31912 master.cpp:930] Master terminating
I1219 09:51:47.851934 31899 hierarchical.cpp:496] Removed slave
bded856d-1c7f-4fad-a8bc-3629ba8c59d3-S0
I1219 09:51:47.855919 31907 slave.cpp:3417] [email protected]:36408 exited
W1219 09:51:47.856021 31907 slave.cpp:3420] Master disconnected! Waiting for a
new master to be elected
I1219 09:51:47.908278 31878 slave.cpp:601] Slave terminating
[ FAILED ] PersistentVolumeTest.BadACLDropCreateAndDestroy (15298 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
