[ https://issues.apache.org/jira/browse/MESOS-4208?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Benjamin Hindman updated MESOS-4208: ------------------------------------ Shepherd: Jie Yu Sprint: Mesosphere Sprint 26 > PersistentVolumeTest.BadACLDropCreateAndDestroy is flaky > -------------------------------------------------------- > > Key: MESOS-4208 > URL: https://issues.apache.org/jira/browse/MESOS-4208 > Project: Mesos > Issue Type: Bug > Reporter: Jie Yu > Assignee: Greg Mann > Labels: flaky-test, mesosphere, persistent-volumes > > {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 > 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) > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)