[ 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 master@172.17.0.3: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 master@172.17.0.3: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 master@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 master@172.17.0.3:36408
I1219 09:51:32.706738 31907 slave.cpp:792] Authenticating with master master@172.17.0.3: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 master@172.17.0.3: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 master@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3:36408
I1219 09:51:32.762373 31897 sched.cpp:262] New master detected at master@172.17.0.3: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 master@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3:36408 disconnected
I1219 09:51:47.829169 31909 master.cpp:2493] Disconnecting framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3:36408
I1219 09:51:47.829200 31909 master.cpp:2517] Deactivating framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3:36408
I1219 09:51:47.829366 31909 master.cpp:1154] Giving framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3: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 scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3:36408
I1219 09:51:47.831748 31907 master.cpp:5835] Removing framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 (creator-framework) at scheduler-d2c3fe43-4283-4153-8ee5-533ebc1ac5ce@172.17.0.3:36408
I1219 09:51:47.833314 31897 slave.cpp:2012] Asked to shut down framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0001 by master@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3:36408 disconnected
I1219 09:51:47.843521 31908 master.cpp:2493] Disconnecting framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3:36408
I1219 09:51:47.843663 31908 master.cpp:2517] Deactivating framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3:36408
I1219 09:51:47.845077 31908 master.cpp:1154] Giving framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3: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 scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3:36408
I1219 09:51:47.848068 31902 master.cpp:5835] Removing framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 (default) at scheduler-0333dddc-4b41-40ed-8853-a1aadf1f1879@172.17.0.3:36408
I1219 09:51:47.848553 31902 slave.cpp:2012] Asked to shut down framework bded856d-1c7f-4fad-a8bc-3629ba8c59d3-0000 by master@172.17.0.3: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] master@172.17.0.3: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)
Bug
Major