[
https://issues.apache.org/jira/browse/MESOS-4542?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15121269#comment-15121269
]
Alexander Rukletsov commented on MESOS-4542:
--------------------------------------------
Looks like the test became flaky after we stopped offering unreserved resources
beyond quota in https://reviews.apache.org/r/42835. Hence the allocator offers
rescinded resources to {{framework1}} if allocation happens before the test
finishes, which violates the expectation that {{framework1}} receives resources
only once. Since we do not really care about allocations in this test but
rather about rescinded resources, a possible fix would be to just ignore
subsequent allocations.
> MasterQuotaTest.AvailableResourcesAfterRescinding is flaky.
> -----------------------------------------------------------
>
> Key: MESOS-4542
> URL: https://issues.apache.org/jira/browse/MESOS-4542
> Project: Mesos
> Issue Type: Bug
> Components: allocation, master, test
> Reporter: Alexander Rukletsov
> Assignee: Alexander Rukletsov
> Labels: flaky-test, mesosphere
>
> Can be reproduced by running {{GLOG_v=1
> GTEST_FILTER="MasterQuotaTest.AvailableResourcesAfterRescinding"
> ./bin/mesos-tests.sh --gtest_shuffle --gtest_break_on_failure
> --gtest_repeat=1000 --verbose}}.
> h5. Verbose log from a bad run:
> {code}
> [ RUN ] MasterQuotaTest.AvailableResourcesAfterRescinding
> I0128 12:20:27.568657 2080858880 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.570142 2080858880 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.583225 2080858880 leveldb.cpp:174] Opened db in 6241us
> I0128 12:20:27.584353 2080858880 leveldb.cpp:181] Compacted db in 1026us
> I0128 12:20:27.584429 2080858880 leveldb.cpp:196] Created db iterator in 12us
> I0128 12:20:27.584442 2080858880 leveldb.cpp:202] Seeked to beginning of db
> in 7us
> I0128 12:20:27.584453 2080858880 leveldb.cpp:271] Iterated through 0 keys in
> the db in 6us
> I0128 12:20:27.584475 2080858880 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0128 12:20:27.584918 300445696 recover.cpp:447] Starting replica recovery
> I0128 12:20:27.585113 300445696 recover.cpp:473] Replica is in EMPTY status
> I0128 12:20:27.585916 297226240 replica.cpp:673] Replica in EMPTY status
> received a broadcasted recover request from (18274)@192.168.178.24:51278
> I0128 12:20:27.586086 297762816 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I0128 12:20:27.586449 297226240 recover.cpp:564] Updating replica status to
> STARTING
> I0128 12:20:27.587204 300445696 leveldb.cpp:304] Persisting metadata (8
> bytes) to leveldb took 624us
> I0128 12:20:27.587242 300445696 replica.cpp:320] Persisted replica status to
> STARTING
> I0128 12:20:27.587376 299372544 recover.cpp:473] Replica is in STARTING status
> I0128 12:20:27.588050 300982272 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (18275)@192.168.178.24:51278
> I0128 12:20:27.588235 300445696 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I0128 12:20:27.588572 297762816 recover.cpp:564] Updating replica status to
> VOTING
> I0128 12:20:27.588850 297226240 leveldb.cpp:304] Persisting metadata (8
> bytes) to leveldb took 140us
> I0128 12:20:27.588879 297226240 replica.cpp:320] Persisted replica status to
> VOTING
> I0128 12:20:27.588975 299909120 recover.cpp:578] Successfully joined the
> Paxos group
> I0128 12:20:27.589154 299909120 recover.cpp:462] Recover process terminated
> I0128 12:20:27.599486 298835968 master.cpp:374] Master
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7 (alexr.fritz.box) started on
> 192.168.178.24:51278
> I0128 12:20:27.599520 298835968 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="50ms" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/private/tmp/NlzPSo/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --http_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="25secs" --registry_strict="true"
> --roles="role1,role2" --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui"
> --work_dir="/private/tmp/NlzPSo/master" --zk_session_timeout="10secs"
> I0128 12:20:27.599753 298835968 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0128 12:20:27.599769 298835968 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0128 12:20:27.599781 298835968 credentials.hpp:35] Loading credentials for
> authentication from '/private/tmp/NlzPSo/credentials'
> I0128 12:20:27.600082 298835968 master.cpp:466] Using default 'crammd5'
> authenticator
> I0128 12:20:27.600163 298835968 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0128 12:20:27.600327 298835968 master.cpp:569] Authorization enabled
> W0128 12:20:27.600345 298835968 master.cpp:629] The '--roles' flag is
> deprecated. This flag will be removed in the future. See the Mesos 0.27
> upgrade notes for more information
> I0128 12:20:27.600497 297762816 whitelist_watcher.cpp:77] No whitelist given
> I0128 12:20:27.600503 297226240 hierarchical.cpp:144] Initialized
> hierarchical allocator process
> I0128 12:20:27.601965 297226240 master.cpp:1710] The newly elected leader is
> master@192.168.178.24:51278 with id 531344bd-56f4-4e4f-8f6f-a6a9d36058c7
> I0128 12:20:27.601995 297226240 master.cpp:1723] Elected as the leading
> master!
> I0128 12:20:27.602007 297226240 master.cpp:1468] Recovering from registrar
> I0128 12:20:27.602083 300445696 registrar.cpp:307] Recovering registrar
> I0128 12:20:27.602460 297226240 log.cpp:659] Attempting to start the writer
> I0128 12:20:27.603514 299909120 replica.cpp:493] Replica received implicit
> promise request from (18277)@192.168.178.24:51278 with proposal 1
> I0128 12:20:27.603734 299909120 leveldb.cpp:304] Persisting metadata (8
> bytes) to leveldb took 205us
> I0128 12:20:27.603768 299909120 replica.cpp:342] Persisted promised to 1
> I0128 12:20:27.604194 299909120 coordinator.cpp:238] Coordinator attempting
> to fill missing positions
> I0128 12:20:27.605311 299372544 replica.cpp:388] Replica received explicit
> promise request from (18278)@192.168.178.24:51278 for position 0 with
> proposal 2
> I0128 12:20:27.605468 299372544 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 133us
> I0128 12:20:27.605494 299372544 replica.cpp:712] Persisted action at 0
> I0128 12:20:27.606441 298835968 replica.cpp:537] Replica received write
> request for position 0 from (18279)@192.168.178.24:51278
> I0128 12:20:27.606492 298835968 leveldb.cpp:436] Reading position from
> leveldb took 29us
> I0128 12:20:27.606665 298835968 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 151us
> I0128 12:20:27.606688 298835968 replica.cpp:712] Persisted action at 0
> I0128 12:20:27.607244 297226240 replica.cpp:691] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I0128 12:20:27.607409 297226240 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 152us
> I0128 12:20:27.607441 297226240 replica.cpp:712] Persisted action at 0
> I0128 12:20:27.607457 297226240 replica.cpp:697] Replica learned NOP action
> at position 0
> I0128 12:20:27.607853 297226240 log.cpp:675] Writer started with ending
> position 0
> I0128 12:20:27.608649 299372544 leveldb.cpp:436] Reading position from
> leveldb took 158us
> I0128 12:20:27.609539 298835968 registrar.cpp:340] Successfully fetched the
> registry (0B) in 7.426816ms
> I0128 12:20:27.609763 298835968 registrar.cpp:439] Applied 1 operations in
> 54us; attempting to update the 'registry'
> I0128 12:20:27.610216 300982272 log.cpp:683] Attempting to append 186 bytes
> to the log
> I0128 12:20:27.610297 298835968 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 1
> I0128 12:20:27.611016 299909120 replica.cpp:537] Replica received write
> request for position 1 from (18280)@192.168.178.24:51278
> I0128 12:20:27.611188 299909120 leveldb.cpp:341] Persisting action (205
> bytes) to leveldb took 153us
> I0128 12:20:27.611222 299909120 replica.cpp:712] Persisted action at 1
> I0128 12:20:27.611843 299909120 replica.cpp:691] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I0128 12:20:27.612004 299909120 leveldb.cpp:341] Persisting action (207
> bytes) to leveldb took 147us
> I0128 12:20:27.612035 299909120 replica.cpp:712] Persisted action at 1
> I0128 12:20:27.612052 299909120 replica.cpp:697] Replica learned APPEND
> action at position 1
> I0128 12:20:27.612742 300982272 registrar.cpp:484] Successfully updated the
> 'registry' in 2.924032ms
> I0128 12:20:27.612846 300982272 registrar.cpp:370] Successfully recovered
> registrar
> I0128 12:20:27.612936 298835968 log.cpp:702] Attempting to truncate the log
> to 1
> I0128 12:20:27.613005 297762816 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 2
> I0128 12:20:27.613323 298299392 master.cpp:1520] Recovered 0 slaves from the
> Registry (147B) ; allowing 10mins for slaves to re-register
> I0128 12:20:27.613364 298835968 hierarchical.cpp:171] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0128 12:20:27.613966 300445696 replica.cpp:537] Replica received write
> request for position 2 from (18281)@192.168.178.24:51278
> I0128 12:20:27.614131 300445696 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 151us
> I0128 12:20:27.614166 300445696 replica.cpp:712] Persisted action at 2
> I0128 12:20:27.614660 299372544 replica.cpp:691] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I0128 12:20:27.614828 299372544 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 158us
> I0128 12:20:27.614876 299372544 leveldb.cpp:399] Deleting ~1 keys from
> leveldb took 28us
> I0128 12:20:27.614898 299372544 replica.cpp:712] Persisted action at 2
> I0128 12:20:27.614915 299372544 replica.cpp:697] Replica learned TRUNCATE
> action at position 2
> I0128 12:20:27.625591 2080858880 containerizer.cpp:143] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> I0128 12:20:27.629758 298299392 slave.cpp:192] Slave started on
> 871)@192.168.178.24:51278
> I0128 12:20:27.629791 298299392 slave.cpp:193] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_gS9Qcf/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_gS9Qcf/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="/Users/alex/Projects/mesos/build/default/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
> --version="false"
> --work_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_gS9Qcf"
> I0128 12:20:27.630067 298299392 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_gS9Qcf/credential'
> I0128 12:20:27.630223 298299392 slave.cpp:323] Slave using credential for:
> test-principal
> I0128 12:20:27.630360 298299392 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.630818 298299392 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0128 12:20:27.630869 298299392 slave.cpp:471] Slave attributes: [ ]
> I0128 12:20:27.630882 298299392 slave.cpp:476] Slave hostname: alexr.fritz.box
> I0128 12:20:27.631352 300982272 state.cpp:58] Recovering state from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_gS9Qcf/meta'
> I0128 12:20:27.631515 299909120 status_update_manager.cpp:200] Recovering
> status update manager
> I0128 12:20:27.631702 298835968 containerizer.cpp:390] Recovering
> containerizer
> I0128 12:20:27.632589 297226240 provisioner.cpp:245] Provisioner recovery
> complete
> I0128 12:20:27.632807 298835968 slave.cpp:4495] Finished recovery
> I0128 12:20:27.633539 298835968 slave.cpp:4667] Querying resource estimator
> for oversubscribable resources
> I0128 12:20:27.633752 300445696 status_update_manager.cpp:174] Pausing
> sending status updates
> I0128 12:20:27.633754 298835968 slave.cpp:795] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.633806 298835968 slave.cpp:858] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.633824 298835968 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.633903 298835968 slave.cpp:831] Detecting new master
> I0128 12:20:27.633913 299372544 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.634016 298835968 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0128 12:20:27.634076 297226240 master.cpp:5521] Authenticating
> slave(871)@192.168.178.24:51278
> I0128 12:20:27.634130 299372544 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1741)@192.168.178.24:51278
> I0128 12:20:27.634255 297226240 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.634348 300982272 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.634367 300982272 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.634454 298835968 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.634515 298835968 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.634572 298835968 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.634706 297226240 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.634757 297226240 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.634771 297226240 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.634793 297226240 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.634809 297226240 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.634819 297226240 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.634827 297226240 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.634893 297226240 authenticator.cpp:317] Authentication success
> I0128 12:20:27.634958 298835968 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.635030 298299392 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(871)@192.168.178.24:51278
> I0128 12:20:27.635079 300445696 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1741)@192.168.178.24:51278
> I0128 12:20:27.635195 299372544 slave.cpp:926] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.635273 299372544 slave.cpp:1320] Will retry registration in
> 5.823453ms if necessary
> I0128 12:20:27.635365 299909120 master.cpp:4235] Registering slave at
> slave(871)@192.168.178.24:51278 (alexr.fritz.box) with id
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0
> I0128 12:20:27.635542 297762816 registrar.cpp:439] Applied 1 operations in
> 41us; attempting to update the 'registry'
> I0128 12:20:27.635889 299372544 log.cpp:683] Attempting to append 358 bytes
> to the log
> I0128 12:20:27.636011 298299392 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 3
> I0128 12:20:27.636693 300982272 replica.cpp:537] Replica received write
> request for position 3 from (18295)@192.168.178.24:51278
> I0128 12:20:27.636860 300982272 leveldb.cpp:341] Persisting action (377
> bytes) to leveldb took 139us
> I0128 12:20:27.636885 300982272 replica.cpp:712] Persisted action at 3
> I0128 12:20:27.637380 299909120 replica.cpp:691] Replica received learned
> notice for position 3 from @0.0.0.0:0
> I0128 12:20:27.637547 299909120 leveldb.cpp:341] Persisting action (379
> bytes) to leveldb took 132us
> I0128 12:20:27.637573 299909120 replica.cpp:712] Persisted action at 3
> I0128 12:20:27.637589 299909120 replica.cpp:697] Replica learned APPEND
> action at position 3
> I0128 12:20:27.638362 298835968 registrar.cpp:484] Successfully updated the
> 'registry' in 2.77504ms
> I0128 12:20:27.638589 300445696 log.cpp:702] Attempting to truncate the log
> to 3
> I0128 12:20:27.638684 298299392 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 4
> I0128 12:20:27.638825 300445696 slave.cpp:3435] Received ping from
> slave-observer(871)@192.168.178.24:51278
> I0128 12:20:27.639081 300982272 hierarchical.cpp:473] Added slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0 (alexr.fritz.box) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0128 12:20:27.639117 299909120 master.cpp:4303] Registered slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0 at slave(871)@192.168.178.24:51278
> (alexr.fritz.box) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0128 12:20:27.639165 300982272 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.639168 297226240 slave.cpp:970] Registered with master
> master@192.168.178.24:51278; given slave ID
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0
> I0128 12:20:27.639189 297226240 fetcher.cpp:81] Clearing fetcher cache
> I0128 12:20:27.639183 300982272 hierarchical.cpp:1116] Performed allocation
> for slave 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0 in 77us
> I0128 12:20:27.639348 297762816 status_update_manager.cpp:181] Resuming
> sending status updates
> I0128 12:20:27.639519 298835968 replica.cpp:537] Replica received write
> request for position 4 from (18296)@192.168.178.24:51278
> I0128 12:20:27.639678 298835968 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 142us
> I0128 12:20:27.639708 298835968 replica.cpp:712] Persisted action at 4
> I0128 12:20:27.640115 300982272 replica.cpp:691] Replica received learned
> notice for position 4 from @0.0.0.0:0
> I0128 12:20:27.640276 300982272 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 137us
> I0128 12:20:27.640312 300982272 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 21us
> I0128 12:20:27.640326 300982272 replica.cpp:712] Persisted action at 4
> I0128 12:20:27.640336 300982272 replica.cpp:697] Replica learned TRUNCATE
> action at position 4
> I0128 12:20:27.642145 297226240 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_gS9Qcf/meta/slaves/531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0/slave.info'
> I0128 12:20:27.643354 297226240 slave.cpp:1029] Forwarding total
> oversubscribed resources
> I0128 12:20:27.643458 300445696 master.cpp:4644] Received update of slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0 at slave(871)@192.168.178.24:51278
> (alexr.fritz.box) with total oversubscribed resources
> I0128 12:20:27.643710 298299392 hierarchical.cpp:531] Slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0 (alexr.fritz.box) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0128 12:20:27.643769 298299392 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.643805 298299392 hierarchical.cpp:1116] Performed allocation
> for slave 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0 in 78us
> I0128 12:20:27.644645 2080858880 containerizer.cpp:143] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> I0128 12:20:27.649093 297226240 slave.cpp:192] Slave started on
> 872)@192.168.178.24:51278
> I0128 12:20:27.649138 297226240 slave.cpp:193] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_6ycfWv/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_6ycfWv/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="/Users/alex/Projects/mesos/build/default/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
> --version="false"
> --work_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_6ycfWv"
> I0128 12:20:27.649353 297226240 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_6ycfWv/credential'
> I0128 12:20:27.649451 297226240 slave.cpp:323] Slave using credential for:
> test-principal
> I0128 12:20:27.649569 297226240 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.650039 297226240 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0128 12:20:27.650085 297226240 slave.cpp:471] Slave attributes: [ ]
> I0128 12:20:27.650096 297226240 slave.cpp:476] Slave hostname: alexr.fritz.box
> I0128 12:20:27.650509 299909120 state.cpp:58] Recovering state from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_6ycfWv/meta'
> I0128 12:20:27.650699 298299392 status_update_manager.cpp:200] Recovering
> status update manager
> I0128 12:20:27.650701 300445696 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.650738 300445696 hierarchical.cpp:1096] Performed allocation
> for 1 slaves in 101us
> I0128 12:20:27.650887 297226240 containerizer.cpp:390] Recovering
> containerizer
> I0128 12:20:27.651747 299909120 provisioner.cpp:245] Provisioner recovery
> complete
> I0128 12:20:27.651974 300982272 slave.cpp:4495] Finished recovery
> I0128 12:20:27.653733 300982272 slave.cpp:4667] Querying resource estimator
> for oversubscribable resources
> I0128 12:20:27.653928 300982272 slave.cpp:795] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.653928 299372544 status_update_manager.cpp:174] Pausing
> sending status updates
> I0128 12:20:27.653975 300982272 slave.cpp:858] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.653991 300982272 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.654091 300982272 slave.cpp:831] Detecting new master
> I0128 12:20:27.654098 297226240 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.654216 300982272 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0128 12:20:27.654276 297762816 master.cpp:5521] Authenticating
> slave(872)@192.168.178.24:51278
> I0128 12:20:27.654350 299909120 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1742)@192.168.178.24:51278
> I0128 12:20:27.654498 298299392 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.654602 300982272 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.654625 300982272 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.654700 299909120 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.654752 299909120 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.654819 299909120 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.654940 299372544 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.654965 299372544 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.654978 299372544 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.654997 299372544 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.655012 299372544 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.655024 299372544 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.655031 299372544 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.655047 299372544 authenticator.cpp:317] Authentication success
> I0128 12:20:27.655143 299909120 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.655120 297762816 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(872)@192.168.178.24:51278
> I0128 12:20:27.655163 299372544 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1742)@192.168.178.24:51278
> I0128 12:20:27.655326 300445696 slave.cpp:926] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.655465 300445696 slave.cpp:1320] Will retry registration in
> 13.985296ms if necessary
> I0128 12:20:27.655565 299909120 master.cpp:4235] Registering slave at
> slave(872)@192.168.178.24:51278 (alexr.fritz.box) with id
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1
> I0128 12:20:27.655823 300982272 registrar.cpp:439] Applied 1 operations in
> 64us; attempting to update the 'registry'
> I0128 12:20:27.656354 297226240 log.cpp:683] Attempting to append 527 bytes
> to the log
> I0128 12:20:27.656429 300445696 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 5
> I0128 12:20:27.657187 300445696 replica.cpp:537] Replica received write
> request for position 5 from (18310)@192.168.178.24:51278
> I0128 12:20:27.657429 300445696 leveldb.cpp:341] Persisting action (546
> bytes) to leveldb took 224us
> I0128 12:20:27.657464 300445696 replica.cpp:712] Persisted action at 5
> I0128 12:20:27.658007 300445696 replica.cpp:691] Replica received learned
> notice for position 5 from @0.0.0.0:0
> I0128 12:20:27.658190 300445696 leveldb.cpp:341] Persisting action (548
> bytes) to leveldb took 170us
> I0128 12:20:27.658223 300445696 replica.cpp:712] Persisted action at 5
> I0128 12:20:27.658239 300445696 replica.cpp:697] Replica learned APPEND
> action at position 5
> I0128 12:20:27.659104 300982272 registrar.cpp:484] Successfully updated the
> 'registry' in 3.227904ms
> I0128 12:20:27.659373 298835968 log.cpp:702] Attempting to truncate the log
> to 5
> I0128 12:20:27.659446 298299392 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 6
> I0128 12:20:27.659636 300982272 slave.cpp:3435] Received ping from
> slave-observer(872)@192.168.178.24:51278
> I0128 12:20:27.659855 297226240 hierarchical.cpp:473] Added slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1 (alexr.fritz.box) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0128 12:20:27.659960 297226240 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.659936 297762816 master.cpp:4303] Registered slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1 at slave(872)@192.168.178.24:51278
> (alexr.fritz.box) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0128 12:20:27.659981 297226240 hierarchical.cpp:1116] Performed allocation
> for slave 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1 in 80us
> I0128 12:20:27.659986 299909120 slave.cpp:970] Registered with master
> master@192.168.178.24:51278; given slave ID
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1
> I0128 12:20:27.660013 299909120 fetcher.cpp:81] Clearing fetcher cache
> I0128 12:20:27.660092 297226240 replica.cpp:537] Replica received write
> request for position 6 from (18311)@192.168.178.24:51278
> I0128 12:20:27.660246 297226240 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 131us
> I0128 12:20:27.660270 297226240 replica.cpp:712] Persisted action at 6
> I0128 12:20:27.660454 300445696 status_update_manager.cpp:181] Resuming
> sending status updates
> I0128 12:20:27.660742 299372544 replica.cpp:691] Replica received learned
> notice for position 6 from @0.0.0.0:0
> I0128 12:20:27.660924 299372544 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 209us
> I0128 12:20:27.661015 299372544 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 37us
> I0128 12:20:27.661039 299372544 replica.cpp:712] Persisted action at 6
> I0128 12:20:27.661061 299372544 replica.cpp:697] Replica learned TRUNCATE
> action at position 6
> I0128 12:20:27.661752 299909120 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_6ycfWv/meta/slaves/531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1/slave.info'
> I0128 12:20:27.662113 299909120 slave.cpp:1029] Forwarding total
> oversubscribed resources
> I0128 12:20:27.662199 297762816 master.cpp:4644] Received update of slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1 at slave(872)@192.168.178.24:51278
> (alexr.fritz.box) with total oversubscribed resources
> I0128 12:20:27.662508 297762816 hierarchical.cpp:531] Slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1 (alexr.fritz.box) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0128 12:20:27.662577 297762816 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.662590 297762816 hierarchical.cpp:1116] Performed allocation
> for slave 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1 in 51us
> I0128 12:20:27.663261 2080858880 containerizer.cpp:143] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> I0128 12:20:27.669075 299372544 slave.cpp:192] Slave started on
> 873)@192.168.178.24:51278
> I0128 12:20:27.669107 299372544 slave.cpp:193] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_eAr35P/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_eAr35P/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="/Users/alex/Projects/mesos/build/default/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
> --version="false"
> --work_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_eAr35P"
> I0128 12:20:27.669395 299372544 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_eAr35P/credential'
> I0128 12:20:27.669497 299372544 slave.cpp:323] Slave using credential for:
> test-principal
> I0128 12:20:27.669631 299372544 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.670105 299372544 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0128 12:20:27.670146 299372544 slave.cpp:471] Slave attributes: [ ]
> I0128 12:20:27.670155 299372544 slave.cpp:476] Slave hostname: alexr.fritz.box
> I0128 12:20:27.670567 298835968 state.cpp:58] Recovering state from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_eAr35P/meta'
> I0128 12:20:27.670752 300445696 status_update_manager.cpp:200] Recovering
> status update manager
> I0128 12:20:27.670913 300445696 containerizer.cpp:390] Recovering
> containerizer
> I0128 12:20:27.671908 297226240 provisioner.cpp:245] Provisioner recovery
> complete
> I0128 12:20:27.672124 298835968 slave.cpp:4495] Finished recovery
> I0128 12:20:27.673331 298835968 slave.cpp:4667] Querying resource estimator
> for oversubscribable resources
> I0128 12:20:27.673528 297762816 status_update_manager.cpp:174] Pausing
> sending status updates
> I0128 12:20:27.673527 298835968 slave.cpp:795] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.673573 298835968 slave.cpp:858] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.673599 298835968 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.673671 298835968 slave.cpp:831] Detecting new master
> I0128 12:20:27.673686 298299392 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.673797 298835968 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0128 12:20:27.673849 300982272 master.cpp:5521] Authenticating
> slave(873)@192.168.178.24:51278
> I0128 12:20:27.673909 300445696 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1743)@192.168.178.24:51278
> I0128 12:20:27.674026 297226240 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.674127 299909120 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.674154 299909120 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.674247 297762816 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.674293 297762816 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.674357 299909120 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.674450 299909120 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.674471 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.674484 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.674505 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.674522 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.674535 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.674545 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.674558 299909120 authenticator.cpp:317] Authentication success
> I0128 12:20:27.674621 297762816 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.674667 299372544 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(873)@192.168.178.24:51278
> I0128 12:20:27.674734 298835968 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1743)@192.168.178.24:51278
> I0128 12:20:27.674832 298299392 slave.cpp:926] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.674908 298299392 slave.cpp:1320] Will retry registration in
> 13.363505ms if necessary
> I0128 12:20:27.674993 297226240 master.cpp:4235] Registering slave at
> slave(873)@192.168.178.24:51278 (alexr.fritz.box) with id
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2
> I0128 12:20:27.675194 299372544 registrar.cpp:439] Applied 1 operations in
> 52us; attempting to update the 'registry'
> I0128 12:20:27.675604 300445696 log.cpp:683] Attempting to append 696 bytes
> to the log
> I0128 12:20:27.675693 297762816 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 7
> I0128 12:20:27.676316 297226240 replica.cpp:537] Replica received write
> request for position 7 from (18325)@192.168.178.24:51278
> I0128 12:20:27.676472 297226240 leveldb.cpp:341] Persisting action (715
> bytes) to leveldb took 146us
> I0128 12:20:27.676506 297226240 replica.cpp:712] Persisted action at 7
> I0128 12:20:27.677014 300982272 replica.cpp:691] Replica received learned
> notice for position 7 from @0.0.0.0:0
> I0128 12:20:27.677176 300982272 leveldb.cpp:341] Persisting action (717
> bytes) to leveldb took 138us
> I0128 12:20:27.677201 300982272 replica.cpp:712] Persisted action at 7
> I0128 12:20:27.677211 300982272 replica.cpp:697] Replica learned APPEND
> action at position 7
> I0128 12:20:27.678407 299909120 registrar.cpp:484] Successfully updated the
> 'registry' in 3.181056ms
> I0128 12:20:27.678652 300982272 log.cpp:702] Attempting to truncate the log
> to 7
> I0128 12:20:27.678741 297762816 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 8
> I0128 12:20:27.678907 300445696 slave.cpp:3435] Received ping from
> slave-observer(873)@192.168.178.24:51278
> I0128 12:20:27.679098 297762816 hierarchical.cpp:473] Added slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2 (alexr.fritz.box) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0128 12:20:27.679177 297762816 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.679195 297762816 hierarchical.cpp:1116] Performed allocation
> for slave 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2 in 73us
> I0128 12:20:27.679214 299372544 slave.cpp:970] Registered with master
> master@192.168.178.24:51278; given slave ID
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2
> I0128 12:20:27.679186 298299392 master.cpp:4303] Registered slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2 at slave(873)@192.168.178.24:51278
> (alexr.fritz.box) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0128 12:20:27.679239 299372544 fetcher.cpp:81] Clearing fetcher cache
> I0128 12:20:27.679404 298835968 status_update_manager.cpp:181] Resuming
> sending status updates
> I0128 12:20:27.679461 300445696 replica.cpp:537] Replica received write
> request for position 8 from (18326)@192.168.178.24:51278
> I0128 12:20:27.679652 300445696 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 182us
> I0128 12:20:27.679687 300445696 replica.cpp:712] Persisted action at 8
> I0128 12:20:27.679913 299372544 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_eAr35P/meta/slaves/531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2/slave.info'
> I0128 12:20:27.680150 298835968 replica.cpp:691] Replica received learned
> notice for position 8 from @0.0.0.0:0
> I0128 12:20:27.680279 299372544 slave.cpp:1029] Forwarding total
> oversubscribed resources
> I0128 12:20:27.680302 298835968 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 140us
> I0128 12:20:27.680351 298835968 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 28us
> I0128 12:20:27.680371 298835968 replica.cpp:712] Persisted action at 8
> I0128 12:20:27.680377 299372544 master.cpp:4644] Received update of slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2 at slave(873)@192.168.178.24:51278
> (alexr.fritz.box) with total oversubscribed resources
> I0128 12:20:27.680387 298835968 replica.cpp:697] Replica learned TRUNCATE
> action at position 8
> I0128 12:20:27.680680 299909120 hierarchical.cpp:531] Slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2 (alexr.fritz.box) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0128 12:20:27.680749 299909120 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.680768 299909120 hierarchical.cpp:1116] Performed allocation
> for slave 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2 in 60us
> I0128 12:20:27.682180 2080858880 sched.cpp:222] Version: 0.28.0
> I0128 12:20:27.682505 298299392 sched.cpp:326] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.682551 298299392 sched.cpp:382] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.682566 298299392 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.682714 300982272 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.682870 300445696 master.cpp:5521] Authenticating
> scheduler-05b9ac89-54ac-4d24-84e7-bb9cedfa77c4@192.168.178.24:51278
> I0128 12:20:27.682965 298835968 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1744)@192.168.178.24:51278
> I0128 12:20:27.683362 297762816 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.683498 297226240 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.683526 297226240 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.683636 298299392 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.683687 298299392 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.683758 297226240 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.683857 297226240 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.683877 297226240 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.683897 297226240 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.683917 297226240 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.683930 297226240 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.683940 297226240 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.683948 297226240 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.683962 297226240 authenticator.cpp:317] Authentication success
> I0128 12:20:27.684010 299909120 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.684079 300445696 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-05b9ac89-54ac-4d24-84e7-bb9cedfa77c4@192.168.178.24:51278
> I0128 12:20:27.684172 300982272 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1744)@192.168.178.24:51278
> I0128 12:20:27.684288 298835968 sched.cpp:471] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.684306 298835968 sched.cpp:780] Sending SUBSCRIBE call to
> master@192.168.178.24:51278
> I0128 12:20:27.684378 298835968 sched.cpp:813] Will retry registration in
> 1.868624245secs if necessary
> I0128 12:20:27.684437 299909120 master.cpp:2278] Received SUBSCRIBE call for
> framework 'framework(18327)' at
> scheduler-05b9ac89-54ac-4d24-84e7-bb9cedfa77c4@192.168.178.24:51278
> W0128 12:20:27.684456 299909120 master.cpp:2285] Framework at
> scheduler-05b9ac89-54ac-4d24-84e7-bb9cedfa77c4@192.168.178.24:51278
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I0128 12:20:27.684471 299909120 master.cpp:1749] Authorizing framework
> principal '' to receive offers for role 'role1'
> I0128 12:20:27.684675 300445696 master.cpp:2349] Subscribing framework
> framework(18327) with checkpointing disabled and capabilities [ ]
> I0128 12:20:27.684921 297226240 hierarchical.cpp:265] Added framework
> framework(18327)
> I0128 12:20:27.685066 299909120 sched.cpp:707] Framework registered with
> framework(18327)
> I0128 12:20:27.685122 299909120 sched.cpp:721] Scheduler::registered took 48us
> W0128 12:20:27.685184 299372544 slave.cpp:2236] Ignoring updating pid for
> framework framework(18327) because it does not exist
> W0128 12:20:27.685223 299909120 slave.cpp:2236] Ignoring updating pid for
> framework framework(18327) because it does not exist
> W0128 12:20:27.685281 297762816 slave.cpp:2236] Ignoring updating pid for
> framework framework(18327) because it does not exist
> I0128 12:20:27.685915 297226240 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.685945 297226240 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 1015us
> I0128 12:20:27.686295 299372544 master.cpp:5350] Sending 3 offers to
> framework framework(18327) (framework(18327)) at
> scheduler-05b9ac89-54ac-4d24-84e7-bb9cedfa77c4@192.168.178.24:51278
> I0128 12:20:27.686750 298299392 sched.cpp:877] Scheduler::resourceOffers took
> 161us
> I0128 12:20:27.688932 2080858880 sched.cpp:222] Version: 0.28.0
> I0128 12:20:27.689265 298299392 sched.cpp:326] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.689319 298299392 sched.cpp:382] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.689333 298299392 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.689450 300445696 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.689577 300982272 master.cpp:5521] Authenticating
> scheduler-7953b576-d913-4dce-993d-375e2fb34aba@192.168.178.24:51278
> I0128 12:20:27.689654 298835968 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1745)@192.168.178.24:51278
> I0128 12:20:27.689810 299909120 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.689904 300982272 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.689931 300982272 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.690032 297762816 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.690073 297762816 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.690166 298299392 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.690271 298835968 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.690291 298835968 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.690304 298835968 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.690325 298835968 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.690340 298835968 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.690351 298835968 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.690382 298835968 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.690393 298835968 authenticator.cpp:317] Authentication success
> I0128 12:20:27.690402 2080858880 sched.cpp:222] Version: 0.28.0
> I0128 12:20:27.690454 299909120 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.690512 299372544 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-7953b576-d913-4dce-993d-375e2fb34aba@192.168.178.24:51278
> I0128 12:20:27.690639 300982272 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1745)@192.168.178.24:51278
> I0128 12:20:27.690727 299909120 sched.cpp:471] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.690744 299909120 sched.cpp:780] Sending SUBSCRIBE call to
> master@192.168.178.24:51278
> I0128 12:20:27.690832 300445696 sched.cpp:326] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.690878 299909120 sched.cpp:813] Will retry registration in
> 370.645806ms if necessary
> I0128 12:20:27.690896 300445696 sched.cpp:382] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.690909 300445696 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.690932 300982272 master.cpp:2278] Received SUBSCRIBE call for
> framework 'framework(18328)' at
> scheduler-7953b576-d913-4dce-993d-375e2fb34aba@192.168.178.24:51278
> W0128 12:20:27.690953 300982272 master.cpp:2285] Framework at
> scheduler-7953b576-d913-4dce-993d-375e2fb34aba@192.168.178.24:51278
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I0128 12:20:27.690979 300982272 master.cpp:1749] Authorizing framework
> principal '' to receive offers for role 'role2'
> I0128 12:20:27.691057 299372544 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.691160 300982272 master.cpp:5521] Authenticating
> scheduler-1ed5257a-cda6-4cef-aaf1-87934636893e@192.168.178.24:51278
> I0128 12:20:27.691257 298299392 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1746)@192.168.178.24:51278
> I0128 12:20:27.691284 300982272 master.cpp:2349] Subscribing framework
> framework(18328) with checkpointing disabled and capabilities [ ]
> I0128 12:20:27.691396 297762816 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.691516 300445696 hierarchical.cpp:265] Added framework
> framework(18328)
> I0128 12:20:27.691515 299372544 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.691553 299372544 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.691562 298299392 sched.cpp:707] Framework registered with
> framework(18328)
> I0128 12:20:27.691599 300445696 hierarchical.cpp:1403] No resources available
> to allocate!
> W0128 12:20:27.691620 297226240 slave.cpp:2236] Ignoring updating pid for
> framework framework(18328) because it does not exist
> I0128 12:20:27.691627 300445696 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.691629 298835968 authenticator.cpp:203] Received SASL
> authentication start
> W0128 12:20:27.691661 299909120 slave.cpp:2236] Ignoring updating pid for
> framework framework(18328) because it does not exist
> I0128 12:20:27.691656 300445696 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 128us
> I0128 12:20:27.691653 298299392 sched.cpp:721] Scheduler::registered took 86us
> I0128 12:20:27.691680 298835968 authenticator.cpp:325] Authentication
> requires more steps
> W0128 12:20:27.691718 297762816 slave.cpp:2236] Ignoring updating pid for
> framework framework(18328) because it does not exist
> I0128 12:20:27.691797 298299392 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.691896 299372544 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.691917 299372544 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.691929 299372544 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.691947 299372544 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.691962 299372544 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.691973 299372544 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.691982 299372544 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.691993 299372544 authenticator.cpp:317] Authentication success
> I0128 12:20:27.692075 299909120 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.692142 298299392 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-1ed5257a-cda6-4cef-aaf1-87934636893e@192.168.178.24:51278
> I0128 12:20:27.692203 298835968 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1746)@192.168.178.24:51278
> I0128 12:20:27.692313 297762816 sched.cpp:471] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.692330 297762816 sched.cpp:780] Sending SUBSCRIBE call to
> master@192.168.178.24:51278
> I0128 12:20:27.692392 297762816 sched.cpp:813] Will retry registration in
> 284.450047ms if necessary
> I0128 12:20:27.692456 299909120 master.cpp:2278] Received SUBSCRIBE call for
> framework 'framework(18329)' at
> scheduler-1ed5257a-cda6-4cef-aaf1-87934636893e@192.168.178.24:51278
> W0128 12:20:27.692473 299909120 master.cpp:2285] Framework at
> scheduler-1ed5257a-cda6-4cef-aaf1-87934636893e@192.168.178.24:51278
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I0128 12:20:27.692486 299909120 master.cpp:1749] Authorizing framework
> principal '' to receive offers for role 'role2'
> I0128 12:20:27.692632 297762816 master.cpp:2349] Subscribing framework
> framework(18329) with checkpointing disabled and capabilities [ ]
> I0128 12:20:27.692858 298299392 hierarchical.cpp:265] Added framework
> framework(18329)
> I0128 12:20:27.692924 299372544 sched.cpp:707] Framework registered with
> framework(18329)
> W0128 12:20:27.692945 297226240 slave.cpp:2236] Ignoring updating pid for
> framework framework(18329) because it does not exist
> I0128 12:20:27.692952 298299392 hierarchical.cpp:1403] No resources available
> to allocate!
> W0128 12:20:27.692972 297762816 slave.cpp:2236] Ignoring updating pid for
> framework framework(18329) because it does not exist
> I0128 12:20:27.692982 298299392 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.692986 299372544 sched.cpp:721] Scheduler::registered took 52us
> W0128 12:20:27.693003 297226240 slave.cpp:2236] Ignoring updating pid for
> framework framework(18329) because it does not exist
> I0128 12:20:27.693001 298299392 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 124us
> I0128 12:20:27.693220 2080858880 resources.cpp:564] Parsing resources as JSON
> failed: cpus:1;mem:512
> Trying semicolon-delimited string format instead
> I0128 12:20:27.694814 297762816 process.cpp:3141] Handling HTTP event for
> process 'master' with path: '/master/quota'
> I0128 12:20:27.695245 299372544 http.cpp:503] HTTP POST for /master/quota
> from 192.168.178.24:51641
> I0128 12:20:27.695274 299372544 quota_handler.cpp:211] Setting quota from
> request:
> '{"force":false,"guarantee":[{"name":"cpus","role":"*","scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","role":"*","scalar":{"value":512.0},"type":"SCALAR"}],"role":"role2"}'
> I0128 12:20:27.695569 299372544 quota_handler.cpp:446] Authorizing principal
> 'test-principal' to request quota for role 'role2'
> I0128 12:20:27.695719 299372544 quota_handler.cpp:70] Performing capacity
> heuristic check for a set quota request
> I0128 12:20:27.695996 297226240 registrar.cpp:439] Applied 1 operations in
> 77us; attempting to update the 'registry'
> I0128 12:20:27.696362 300445696 log.cpp:683] Attempting to append 770 bytes
> to the log
> I0128 12:20:27.696458 299372544 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 9
> I0128 12:20:27.697157 297226240 replica.cpp:537] Replica received write
> request for position 9 from (18332)@192.168.178.24:51278
> I0128 12:20:27.697350 297226240 leveldb.cpp:341] Persisting action (789
> bytes) to leveldb took 182us
> I0128 12:20:27.697382 297226240 replica.cpp:712] Persisted action at 9
> I0128 12:20:27.697803 297762816 replica.cpp:691] Replica received learned
> notice for position 9 from @0.0.0.0:0
> I0128 12:20:27.697944 297762816 leveldb.cpp:341] Persisting action (791
> bytes) to leveldb took 127us
> I0128 12:20:27.697968 297762816 replica.cpp:712] Persisted action at 9
> I0128 12:20:27.697978 297762816 replica.cpp:697] Replica learned APPEND
> action at position 9
> I0128 12:20:27.699586 297762816 registrar.cpp:484] Successfully updated the
> 'registry' in 3.547904ms
> I0128 12:20:27.699905 300982272 log.cpp:702] Attempting to truncate the log
> to 9
> I0128 12:20:27.700006 298835968 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 10
> I0128 12:20:27.699996 297762816 hierarchical.cpp:1024] Set quota cpus(*):1;
> mem(*):512 for role 'role2'
> I0128 12:20:27.700466 300982272 sched.cpp:903] Rescinded offer
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-O0
> I0128 12:20:27.700542 300982272 sched.cpp:914] Scheduler::offerRescinded took
> 59us
> I0128 12:20:27.700582 297762816 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.700615 297762816 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.700635 297762816 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 607us
> I0128 12:20:27.700886 297762816 hierarchical.cpp:892] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2 from framework framework(18327)
> I0128 12:20:27.701004 299372544 sched.cpp:903] Rescinded offer
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-O1
> I0128 12:20:27.701046 299372544 sched.cpp:914] Scheduler::offerRescinded took
> 29us
> I0128 12:20:27.701098 298299392 replica.cpp:537] Replica received write
> request for position 10 from (18333)@192.168.178.24:51278
> I0128 12:20:27.701093 297762816 hierarchical.cpp:892] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1 from framework framework(18327)
> I0128 12:20:27.701261 298299392 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 237us
> I0128 12:20:27.701382 298299392 replica.cpp:712] Persisted action at 10
> I0128 12:20:27.702061 299909120 replica.cpp:691] Replica received learned
> notice for position 10 from @0.0.0.0:0
> I0128 12:20:27.702244 299909120 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 171us
> I0128 12:20:27.702301 299909120 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 34us
> I0128 12:20:27.702322 299909120 replica.cpp:712] Persisted action at 10
> I0128 12:20:27.702339 299909120 replica.cpp:697] Replica learned TRUNCATE
> action at position 10
> I0128 12:20:27.702792 297762816 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.702831 297762816 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 1644us
> I0128 12:20:27.703033 299909120 master.cpp:5350] Sending 1 offers to
> framework framework(18327) (framework(18327)) at
> scheduler-05b9ac89-54ac-4d24-84e7-bb9cedfa77c4@192.168.178.24:51278
> I0128 12:20:27.703428 299909120 master.cpp:5350] Sending 1 offers to
> framework framework(18328) (framework(18328)) at
> scheduler-7953b576-d913-4dce-993d-375e2fb34aba@192.168.178.24:51278
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
> Function call: resourceOffers(0x7fff5bdd4c88, @0x111e86250 { 144-byte
> object <90-06 1B-0B 01-00 00-00 00-00 00-00 00-00 00-00 00-A9 61-FB FD-7F
> 00-00 70-A9 61-FB FD-7F 00-00 B0-A9 61-FB FD-7F 00-00 F0-B0 61-FB FD-7F 00-00
> 10-B1 61-FB FD-7F 00-00../../../src/tests/master_quota_tests.cpp:899: Failure
> Mock function called more times than expected - returning directly.
> Function call: resourceOffers(0x7fff5bdd4dd0, @0x111c7a250 { 144-byte
> object <90-06 1B-0B 01-00 00-00 00-00 00-00 00-00 00-00 30-C1 C4-FC FD-7F
> 00-00 80-C1 4A-FB FD-7F 00-00 F0-BD 48-FB FD-7F 00-00 E0-64 4A-FB FD-7F 00-00
> D0-56 C0-FC FD-7F 00-00 C0-94 C8-FC FD-7F 00-00 ... 00-00 00-00 00-00 00-00
> 00-00 00-00 00-00 00-00 00-00 00-00 FD-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
> I0128 12:20:27.704130 297762816 master.cpp:1025] Master terminating
> 7*** Aborted at 1453980027 (unix time) try "date -d @1453980027" if you are
> using GNU date ***
> 0-D6 60-FB FD-7F 00-00 ... 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00
> 00-00 00-00 FD-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> })
> Stack trace:
> I0128 12:20:27.704699 299372544 hierarchical.cpp:505] Removed slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S2
> I0128 12:20:27.705009 297226240 hierarchical.cpp:505] Removed slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S1
> I0128 12:20:27.705271 300445696 sched.cpp:877] Scheduler::resourceOffers took
> 1623us
> I0128 12:20:27.705306 299909120 hierarchical.cpp:505] Removed slave
> 531344bd-56f4-4e4f-8f6f-a6a9d36058c7-S0
> I0128 12:20:27.705575 298835968 hierarchical.cpp:326] Removed framework
> framework(18329)
> I0128 12:20:27.705803 298835968 hierarchical.cpp:326] Removed framework
> framework(18328)
> I0128 12:20:27.705878 300445696 slave.cpp:3481] master@192.168.178.24:51278
> exited
> W0128 12:20:27.705901 300445696 slave.cpp:3484] Master disconnected! Waiting
> for a new master to be elected
> I0128 12:20:27.705904 300982272 slave.cpp:3481] master@192.168.178.24:51278
> exited
> W0128 12:20:27.705921 300982272 slave.cpp:3484] Master disconnected! Waiting
> for a new master to be elected
> I0128 12:20:27.705955 300445696 slave.cpp:3481] master@192.168.178.24:51278
> exited
> W0128 12:20:27.705971 300445696 slave.cpp:3484] Master disconnected! Waiting
> for a new master to be elected
> I0128 12:20:27.706085 298835968 hierarchical.cpp:326] Removed framework
> framework(18327)
> I0128 12:20:27.709558 299372544 slave.cpp:667] Slave terminating
> I0128 12:20:27.712924 299372544 slave.cpp:667] Slave terminating
> I0128 12:20:27.716169 299909120 slave.cpp:667] Slave terminating
> PC: @ 0x1054638f5 testing::UnitTest::AddTestPartResult()
> *** SIGSEGV (@0x0) received by PID 98630 (TID 0x111c7b000) stack trace: ***
> @ 0x7fff91018f1a _sigtramp
> @ 0x7fff93077187 malloc
> @ 0x1054630a7 testing::internal::AssertHelper::operator=()
> @ 0x1054cebcb
> testing::internal::GoogleTestFailureReporter::ReportFailure()
> @ 0x103f20058 testing::internal::Expect()
> @ 0x1054a2d86
> testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
> @ 0x104b3ec18 testing::internal::FunctionMockerBase<>::InvokeWith()
> @ 0x104b3ebdb testing::internal::FunctionMocker<>::Invoke()
> @ 0x104b068dd
> mesos::internal::tests::MockScheduler::resourceOffers()
> I0128 12:20:27.756392 299909120 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.756412 299909120 hierarchical.cpp:1096] Performed allocation
> for 0 slaves in 81us
> I0128 12:20:27.808101 297226240 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.808130 297226240 hierarchical.cpp:1096] Performed allocation
> for 0 slaves in 99us
> @ 0x108d500fb mesos::internal::SchedulerProcess::resourceOffers()
> @ 0x108d78d0f ProtobufProcess<>::handler2<>()
> @ 0x108d7ba6b
> _ZNSt3__110__function6__funcINS_6__bindIPFvPN5mesos8internal16SchedulerProcessEMS5_FvRKN7process4UPIDERKNS_6vectorINS3_5OfferENS_9allocatorISC_EEEERKNSB_INS_12basic_stringIcNS_11char_traitsIcEENSD_IcEEEENSD_ISM_EEEEEMNS4_21ResourceOffersMessageEKFRKN6google8protobuf16RepeatedPtrFieldISC_EEvEMST_KFRKNSW_ISM_EEvESA_RKSM_EJRS6_RSS_RS11_RS16_RNS_12placeholders4__phILi1EEERNS1G_ILi2EEEEEENSD_IS1L_EEFvSA_S18_EEclESA_S18_
> @ 0x1080af494 std::__1::function<>::operator()()
> @ 0x108d4932e ProtobufProcess<>::visit()
> I0128 12:20:27.858326 300445696 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.858350 300445696 hierarchical.cpp:1096] Performed allocation
> for 0 slaves in 99us
> @ 0x108d49477 ProtobufProcess<>::visit()
> @ 0x108b099be process::MessageEvent::visit()
> @ 0x108097df1 process::ProcessBase::serve()
> @ 0x10a86d4d0 process::ProcessManager::resume()
> @ 0x10a87d8af
> process::ProcessManager::init_threads()::$_1::operator()()
> @ 0x10a87d522
> _ZNSt3__114__thread_proxyINS_5tupleIJNS_6__bindIZN7process14ProcessManager12init_threadsEvE3$_1JNS_17reference_wrapperIKNS_6atomicIbEEEEEEEEEEEEPvSD_
> @ 0x7fff8f415268 _pthread_body
> @ 0x7fff8f4151e5 _pthread_start
> @ 0x7fff8f41341d thread_start
> zsh: segmentation fault GLOG_v=1
> GTEST_FILTER="MasterQuotaTest.AvailableResourcesAfterRescinding"
> {code}
> h5. Verbose log from a good run:
> {code}
> [ RUN ] MasterQuotaTest.AvailableResourcesAfterRescinding
> I0128 12:20:27.320648 2080858880 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.321002 2080858880 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.327103 2080858880 leveldb.cpp:174] Opened db in 3111us
> I0128 12:20:27.327848 2080858880 leveldb.cpp:181] Compacted db in 700us
> I0128 12:20:27.327899 2080858880 leveldb.cpp:196] Created db iterator in 17us
> I0128 12:20:27.327922 2080858880 leveldb.cpp:202] Seeked to beginning of db
> in 11us
> I0128 12:20:27.327940 2080858880 leveldb.cpp:271] Iterated through 0 keys in
> the db in 11us
> I0128 12:20:27.327973 2080858880 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0128 12:20:27.328737 298299392 recover.cpp:447] Starting replica recovery
> I0128 12:20:27.329010 298299392 recover.cpp:473] Replica is in EMPTY status
> I0128 12:20:27.330369 299909120 replica.cpp:673] Replica in EMPTY status
> received a broadcasted recover request from (18211)@192.168.178.24:51278
> I0128 12:20:27.330749 297226240 recover.cpp:193] Received a recover response
> from a replica in EMPTY status
> I0128 12:20:27.331166 297762816 recover.cpp:564] Updating replica status to
> STARTING
> I0128 12:20:27.331825 300445696 leveldb.cpp:304] Persisting metadata (8
> bytes) to leveldb took 437us
> I0128 12:20:27.331897 300445696 replica.cpp:320] Persisted replica status to
> STARTING
> I0128 12:20:27.332077 300445696 recover.cpp:473] Replica is in STARTING status
> I0128 12:20:27.332474 298299392 master.cpp:374] Master
> bd6f3479-18eb-478d-8a08-a41364ecbd05 (alexr.fritz.box) started on
> 192.168.178.24:51278
> I0128 12:20:27.332520 298299392 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="50ms" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/private/tmp/rkmzt7/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --http_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="25secs" --registry_strict="true"
> --roles="role1,role2" --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui"
> --work_dir="/private/tmp/rkmzt7/master" --zk_session_timeout="10secs"
> I0128 12:20:27.332871 298299392 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0128 12:20:27.332898 298299392 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0128 12:20:27.332957 298299392 credentials.hpp:35] Loading credentials for
> authentication from '/private/tmp/rkmzt7/credentials'
> I0128 12:20:27.333255 300982272 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (18212)@192.168.178.24:51278
> I0128 12:20:27.333359 298299392 master.cpp:466] Using default 'crammd5'
> authenticator
> I0128 12:20:27.333549 298299392 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0128 12:20:27.333550 299909120 recover.cpp:193] Received a recover response
> from a replica in STARTING status
> I0128 12:20:27.333890 298299392 master.cpp:569] Authorization enabled
> W0128 12:20:27.333930 298299392 master.cpp:629] The '--roles' flag is
> deprecated. This flag will be removed in the future. See the Mesos 0.27
> upgrade notes for more information
> I0128 12:20:27.334220 298835968 recover.cpp:564] Updating replica status to
> VOTING
> I0128 12:20:27.334226 300445696 whitelist_watcher.cpp:77] No whitelist given
> I0128 12:20:27.334276 300982272 hierarchical.cpp:144] Initialized
> hierarchical allocator process
> I0128 12:20:27.334724 300982272 leveldb.cpp:304] Persisting metadata (8
> bytes) to leveldb took 242us
> I0128 12:20:27.334772 300982272 replica.cpp:320] Persisted replica status to
> VOTING
> I0128 12:20:27.334895 298835968 recover.cpp:578] Successfully joined the
> Paxos group
> I0128 12:20:27.335198 298835968 recover.cpp:462] Recover process terminated
> I0128 12:20:27.336282 298299392 master.cpp:1710] The newly elected leader is
> master@192.168.178.24:51278 with id bd6f3479-18eb-478d-8a08-a41364ecbd05
> I0128 12:20:27.336321 298299392 master.cpp:1723] Elected as the leading
> master!
> I0128 12:20:27.336340 298299392 master.cpp:1468] Recovering from registrar
> I0128 12:20:27.336454 300982272 registrar.cpp:307] Recovering registrar
> I0128 12:20:27.336956 299909120 log.cpp:659] Attempting to start the writer
> I0128 12:20:27.338927 298299392 replica.cpp:493] Replica received implicit
> promise request from (18214)@192.168.178.24:51278 with proposal 1
> I0128 12:20:27.339247 298299392 leveldb.cpp:304] Persisting metadata (8
> bytes) to leveldb took 291us
> I0128 12:20:27.339287 298299392 replica.cpp:342] Persisted promised to 1
> I0128 12:20:27.340066 297226240 coordinator.cpp:238] Coordinator attempting
> to fill missing positions
> I0128 12:20:27.341961 297226240 replica.cpp:388] Replica received explicit
> promise request from (18215)@192.168.178.24:51278 for position 0 with
> proposal 2
> I0128 12:20:27.342239 297226240 leveldb.cpp:341] Persisting action (8 bytes)
> to leveldb took 247us
> I0128 12:20:27.342278 297226240 replica.cpp:712] Persisted action at 0
> I0128 12:20:27.343778 299372544 replica.cpp:537] Replica received write
> request for position 0 from (18216)@192.168.178.24:51278
> I0128 12:20:27.343852 299372544 leveldb.cpp:436] Reading position from
> leveldb took 42us
> I0128 12:20:27.344118 299372544 leveldb.cpp:341] Persisting action (14 bytes)
> to leveldb took 238us
> I0128 12:20:27.344156 299372544 replica.cpp:712] Persisted action at 0
> I0128 12:20:27.344981 297762816 replica.cpp:691] Replica received learned
> notice for position 0 from @0.0.0.0:0
> I0128 12:20:27.345227 297762816 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 224us
> I0128 12:20:27.345264 297762816 replica.cpp:712] Persisted action at 0
> I0128 12:20:27.345284 297762816 replica.cpp:697] Replica learned NOP action
> at position 0
> I0128 12:20:27.346266 298835968 log.cpp:675] Writer started with ending
> position 0
> I0128 12:20:27.347331 298835968 leveldb.cpp:436] Reading position from
> leveldb took 63us
> I0128 12:20:27.348314 300982272 registrar.cpp:340] Successfully fetched the
> registry (0B) in 11.819264ms
> I0128 12:20:27.348456 300982272 registrar.cpp:439] Applied 1 operations in
> 71us; attempting to update the 'registry'
> I0128 12:20:27.349019 297226240 log.cpp:683] Attempting to append 186 bytes
> to the log
> I0128 12:20:27.349143 300982272 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 1
> I0128 12:20:27.350441 298835968 replica.cpp:537] Replica received write
> request for position 1 from (18217)@192.168.178.24:51278
> I0128 12:20:27.350811 298835968 leveldb.cpp:341] Persisting action (205
> bytes) to leveldb took 337us
> I0128 12:20:27.350846 298835968 replica.cpp:712] Persisted action at 1
> I0128 12:20:27.351572 298835968 replica.cpp:691] Replica received learned
> notice for position 1 from @0.0.0.0:0
> I0128 12:20:27.351801 298835968 leveldb.cpp:341] Persisting action (207
> bytes) to leveldb took 212us
> I0128 12:20:27.351836 298835968 replica.cpp:712] Persisted action at 1
> I0128 12:20:27.351851 298835968 replica.cpp:697] Replica learned APPEND
> action at position 1
> I0128 12:20:27.352608 299372544 registrar.cpp:484] Successfully updated the
> 'registry' in 4.096768ms
> I0128 12:20:27.352735 299372544 registrar.cpp:370] Successfully recovered
> registrar
> I0128 12:20:27.352877 298299392 log.cpp:702] Attempting to truncate the log
> to 1
> I0128 12:20:27.353091 300982272 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 2
> I0128 12:20:27.353314 300445696 master.cpp:1520] Recovered 0 slaves from the
> Registry (147B) ; allowing 10mins for slaves to re-register
> I0128 12:20:27.353341 298835968 hierarchical.cpp:171] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0128 12:20:27.354064 297762816 replica.cpp:537] Replica received write
> request for position 2 from (18218)@192.168.178.24:51278
> I0128 12:20:27.354333 297762816 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 242us
> I0128 12:20:27.354372 297762816 replica.cpp:712] Persisted action at 2
> I0128 12:20:27.355080 299909120 replica.cpp:691] Replica received learned
> notice for position 2 from @0.0.0.0:0
> I0128 12:20:27.355311 299909120 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 214us
> I0128 12:20:27.355362 299909120 leveldb.cpp:399] Deleting ~1 keys from
> leveldb took 27us
> I0128 12:20:27.355382 299909120 replica.cpp:712] Persisted action at 2
> I0128 12:20:27.355398 299909120 replica.cpp:697] Replica learned TRUNCATE
> action at position 2
> I0128 12:20:27.366089 2080858880 containerizer.cpp:143] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> I0128 12:20:27.369942 300445696 slave.cpp:192] Slave started on
> 868)@192.168.178.24:51278
> I0128 12:20:27.369989 300445696 slave.cpp:193] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_UwHS2p/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_UwHS2p/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="/Users/alex/Projects/mesos/build/default/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
> --version="false"
> --work_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_UwHS2p"
> I0128 12:20:27.370420 300445696 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_UwHS2p/credential'
> I0128 12:20:27.370616 300445696 slave.cpp:323] Slave using credential for:
> test-principal
> I0128 12:20:27.370738 300445696 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.371325 300445696 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0128 12:20:27.371383 300445696 slave.cpp:471] Slave attributes: [ ]
> I0128 12:20:27.371399 300445696 slave.cpp:476] Slave hostname: alexr.fritz.box
> I0128 12:20:27.371879 298835968 state.cpp:58] Recovering state from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_UwHS2p/meta'
> I0128 12:20:27.372112 299909120 status_update_manager.cpp:200] Recovering
> status update manager
> I0128 12:20:27.372323 297226240 containerizer.cpp:390] Recovering
> containerizer
> I0128 12:20:27.373388 298835968 provisioner.cpp:245] Provisioner recovery
> complete
> I0128 12:20:27.373706 297226240 slave.cpp:4495] Finished recovery
> I0128 12:20:27.374156 297226240 slave.cpp:4667] Querying resource estimator
> for oversubscribable resources
> I0128 12:20:27.374402 298299392 status_update_manager.cpp:174] Pausing
> sending status updates
> I0128 12:20:27.374408 297226240 slave.cpp:795] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.374454 297226240 slave.cpp:858] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.374469 297226240 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.374605 297226240 slave.cpp:831] Detecting new master
> I0128 12:20:27.374637 300982272 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.374800 297226240 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0128 12:20:27.374876 297762816 master.cpp:5521] Authenticating
> slave(868)@192.168.178.24:51278
> I0128 12:20:27.374999 297226240 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1735)@192.168.178.24:51278
> I0128 12:20:27.375211 298835968 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.375344 297762816 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.375380 297762816 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.375537 298835968 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.375601 298835968 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.375694 297762816 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.375838 299909120 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.375860 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.375871 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.375890 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.375902 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.375911 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.375918 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.375929 299909120 authenticator.cpp:317] Authentication success
> I0128 12:20:27.376003 297762816 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.376076 300445696 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(868)@192.168.178.24:51278
> I0128 12:20:27.376180 298299392 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1735)@192.168.178.24:51278
> I0128 12:20:27.376325 300982272 slave.cpp:926] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.376410 300982272 slave.cpp:1320] Will retry registration in
> 18.436231ms if necessary
> I0128 12:20:27.376557 297762816 master.cpp:4235] Registering slave at
> slave(868)@192.168.178.24:51278 (alexr.fritz.box) with id
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S0
> I0128 12:20:27.376785 298299392 registrar.cpp:439] Applied 1 operations in
> 59us; attempting to update the 'registry'
> I0128 12:20:27.377285 300445696 log.cpp:683] Attempting to append 358 bytes
> to the log
> I0128 12:20:27.377408 297762816 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 3
> I0128 12:20:27.378199 300445696 replica.cpp:537] Replica received write
> request for position 3 from (18232)@192.168.178.24:51278
> I0128 12:20:27.378413 300445696 leveldb.cpp:341] Persisting action (377
> bytes) to leveldb took 192us
> I0128 12:20:27.378446 300445696 replica.cpp:712] Persisted action at 3
> I0128 12:20:27.379106 298299392 replica.cpp:691] Replica received learned
> notice for position 3 from @0.0.0.0:0
> I0128 12:20:27.379331 298299392 leveldb.cpp:341] Persisting action (379
> bytes) to leveldb took 220us
> I0128 12:20:27.379406 298299392 replica.cpp:712] Persisted action at 3
> I0128 12:20:27.379429 298299392 replica.cpp:697] Replica learned APPEND
> action at position 3
> I0128 12:20:27.380581 299372544 registrar.cpp:484] Successfully updated the
> 'registry' in 3.747328ms
> I0128 12:20:27.381187 300445696 log.cpp:702] Attempting to truncate the log
> to 3
> I0128 12:20:27.381304 299909120 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 4
> I0128 12:20:27.381430 300445696 slave.cpp:3435] Received ping from
> slave-observer(868)@192.168.178.24:51278
> I0128 12:20:27.381759 297762816 hierarchical.cpp:473] Added slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S0 (alexr.fritz.box) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0128 12:20:27.381801 297226240 slave.cpp:970] Registered with master
> master@192.168.178.24:51278; given slave ID
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S0
> I0128 12:20:27.381765 298835968 master.cpp:4303] Registered slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S0 at slave(868)@192.168.178.24:51278
> (alexr.fritz.box) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0128 12:20:27.381829 297226240 fetcher.cpp:81] Clearing fetcher cache
> I0128 12:20:27.381908 297762816 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.381950 297762816 hierarchical.cpp:1116] Performed allocation
> for slave bd6f3479-18eb-478d-8a08-a41364ecbd05-S0 in 156us
> I0128 12:20:27.382125 299372544 status_update_manager.cpp:181] Resuming
> sending status updates
> I0128 12:20:27.382279 300982272 replica.cpp:537] Replica received write
> request for position 4 from (18233)@192.168.178.24:51278
> I0128 12:20:27.382540 300982272 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 240us
> I0128 12:20:27.382585 300982272 replica.cpp:712] Persisted action at 4
> I0128 12:20:27.382804 297226240 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_UwHS2p/meta/slaves/bd6f3479-18eb-478d-8a08-a41364ecbd05-S0/slave.info'
> I0128 12:20:27.384191 298299392 replica.cpp:691] Replica received learned
> notice for position 4 from @0.0.0.0:0
> I0128 12:20:27.384424 298299392 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 235us
> I0128 12:20:27.384517 298299392 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 52us
> I0128 12:20:27.384557 298299392 replica.cpp:712] Persisted action at 4
> I0128 12:20:27.384578 298299392 replica.cpp:697] Replica learned TRUNCATE
> action at position 4
> I0128 12:20:27.384601 299372544 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.384624 299372544 hierarchical.cpp:1096] Performed allocation
> for 1 slaves in 124us
> I0128 12:20:27.385365 297226240 slave.cpp:1029] Forwarding total
> oversubscribed resources
> I0128 12:20:27.385526 297226240 master.cpp:4644] Received update of slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S0 at slave(868)@192.168.178.24:51278
> (alexr.fritz.box) with total oversubscribed resources
> I0128 12:20:27.386008 297226240 hierarchical.cpp:531] Slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S0 (alexr.fritz.box) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0128 12:20:27.386137 297226240 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.386155 297226240 hierarchical.cpp:1116] Performed allocation
> for slave bd6f3479-18eb-478d-8a08-a41364ecbd05-S0 in 91us
> I0128 12:20:27.386893 2080858880 containerizer.cpp:143] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> I0128 12:20:27.413722 299909120 slave.cpp:192] Slave started on
> 869)@192.168.178.24:51278
> I0128 12:20:27.413766 299909120 slave.cpp:193] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_TNjwCO/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_TNjwCO/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="/Users/alex/Projects/mesos/build/default/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
> --version="false"
> --work_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_TNjwCO"
> I0128 12:20:27.414484 299909120 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_TNjwCO/credential'
> I0128 12:20:27.414650 299909120 slave.cpp:323] Slave using credential for:
> test-principal
> I0128 12:20:27.416365 299909120 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.418332 299909120 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0128 12:20:27.418475 299909120 slave.cpp:471] Slave attributes: [ ]
> I0128 12:20:27.418500 299909120 slave.cpp:476] Slave hostname: alexr.fritz.box
> I0128 12:20:27.419270 298835968 state.cpp:58] Recovering state from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_TNjwCO/meta'
> I0128 12:20:27.420717 298299392 status_update_manager.cpp:200] Recovering
> status update manager
> I0128 12:20:27.420953 299909120 containerizer.cpp:390] Recovering
> containerizer
> I0128 12:20:27.421883 298835968 provisioner.cpp:245] Provisioner recovery
> complete
> I0128 12:20:27.422145 299909120 slave.cpp:4495] Finished recovery
> I0128 12:20:27.422695 299909120 slave.cpp:4667] Querying resource estimator
> for oversubscribable resources
> I0128 12:20:27.422929 299909120 slave.cpp:795] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.422935 299372544 status_update_manager.cpp:174] Pausing
> sending status updates
> I0128 12:20:27.422971 299909120 slave.cpp:858] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.422986 299909120 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.423073 299909120 slave.cpp:831] Detecting new master
> I0128 12:20:27.423151 298835968 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.423187 299909120 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0128 12:20:27.423333 299909120 master.cpp:5521] Authenticating
> slave(869)@192.168.178.24:51278
> I0128 12:20:27.423431 299909120 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1736)@192.168.178.24:51278
> I0128 12:20:27.423530 297762816 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.423630 299909120 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.423657 299909120 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.423738 299909120 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.423781 299909120 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.423833 299909120 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.423897 299909120 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.423918 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.423931 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.423956 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.423992 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.424006 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.424016 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.424031 299909120 authenticator.cpp:317] Authentication success
> I0128 12:20:27.424095 297762816 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.424125 299909120 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(869)@192.168.178.24:51278
> I0128 12:20:27.424180 299909120 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1736)@192.168.178.24:51278
> I0128 12:20:27.424351 297762816 slave.cpp:926] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.424444 297762816 slave.cpp:1320] Will retry registration in
> 10.561574ms if necessary
> I0128 12:20:27.424577 300982272 master.cpp:4235] Registering slave at
> slave(869)@192.168.178.24:51278 (alexr.fritz.box) with id
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1
> I0128 12:20:27.424949 298835968 registrar.cpp:439] Applied 1 operations in
> 86us; attempting to update the 'registry'
> I0128 12:20:27.425549 297226240 log.cpp:683] Attempting to append 527 bytes
> to the log
> I0128 12:20:27.425662 298835968 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 5
> I0128 12:20:27.426563 300982272 replica.cpp:537] Replica received write
> request for position 5 from (18247)@192.168.178.24:51278
> I0128 12:20:27.426820 300982272 leveldb.cpp:341] Persisting action (546
> bytes) to leveldb took 215us
> I0128 12:20:27.426857 300982272 replica.cpp:712] Persisted action at 5
> I0128 12:20:27.427487 297226240 replica.cpp:691] Replica received learned
> notice for position 5 from @0.0.0.0:0
> I0128 12:20:27.427820 297226240 leveldb.cpp:341] Persisting action (548
> bytes) to leveldb took 197us
> I0128 12:20:27.427855 297226240 replica.cpp:712] Persisted action at 5
> I0128 12:20:27.427940 297226240 replica.cpp:697] Replica learned APPEND
> action at position 5
> I0128 12:20:27.432288 299372544 registrar.cpp:484] Successfully updated the
> 'registry' in 7.28704ms
> I0128 12:20:27.432765 299372544 log.cpp:702] Attempting to truncate the log
> to 5
> I0128 12:20:27.433254 299372544 master.cpp:4303] Registered slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1 at slave(869)@192.168.178.24:51278
> (alexr.fritz.box) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0128 12:20:27.433334 299372544 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 6
> I0128 12:20:27.433584 299372544 hierarchical.cpp:473] Added slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1 (alexr.fritz.box) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0128 12:20:27.433667 299372544 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.433686 299372544 hierarchical.cpp:1116] Performed allocation
> for slave bd6f3479-18eb-478d-8a08-a41364ecbd05-S1 in 78us
> I0128 12:20:27.433753 299372544 slave.cpp:970] Registered with master
> master@192.168.178.24:51278; given slave ID
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1
> I0128 12:20:27.433770 299372544 fetcher.cpp:81] Clearing fetcher cache
> I0128 12:20:27.434334 298299392 status_update_manager.cpp:181] Resuming
> sending status updates
> I0128 12:20:27.435118 298835968 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.435144 298835968 hierarchical.cpp:1096] Performed allocation
> for 2 slaves in 146us
> I0128 12:20:27.435294 297226240 replica.cpp:537] Replica received write
> request for position 6 from (18248)@192.168.178.24:51278
> I0128 12:20:27.435482 297226240 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 173us
> I0128 12:20:27.435516 297226240 replica.cpp:712] Persisted action at 6
> I0128 12:20:27.435883 297226240 replica.cpp:691] Replica received learned
> notice for position 6 from @0.0.0.0:0
> I0128 12:20:27.436043 299372544 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_TNjwCO/meta/slaves/bd6f3479-18eb-478d-8a08-a41364ecbd05-S1/slave.info'
> I0128 12:20:27.436040 297226240 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 148us
> I0128 12:20:27.436091 297226240 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 29us
> I0128 12:20:27.436112 297226240 replica.cpp:712] Persisted action at 6
> I0128 12:20:27.436153 297226240 replica.cpp:697] Replica learned TRUNCATE
> action at position 6
> I0128 12:20:27.436594 299372544 slave.cpp:1029] Forwarding total
> oversubscribed resources
> I0128 12:20:27.436656 299372544 slave.cpp:3435] Received ping from
> slave-observer(869)@192.168.178.24:51278
> I0128 12:20:27.436753 299372544 master.cpp:4644] Received update of slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1 at slave(869)@192.168.178.24:51278
> (alexr.fritz.box) with total oversubscribed resources
> I0128 12:20:27.437094 299372544 hierarchical.cpp:531] Slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1 (alexr.fritz.box) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0128 12:20:27.437599 299372544 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.437620 299372544 hierarchical.cpp:1116] Performed allocation
> for slave bd6f3479-18eb-478d-8a08-a41364ecbd05-S1 in 499us
> I0128 12:20:27.438273 2080858880 containerizer.cpp:143] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> I0128 12:20:27.441591 299372544 slave.cpp:192] Slave started on
> 870)@192.168.178.24:51278
> I0128 12:20:27.441622 299372544 slave.cpp:193] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_iHhziB/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_iHhziB/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="/Users/alex/Projects/mesos/build/default/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
> --version="false"
> --work_dir="/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_iHhziB"
> I0128 12:20:27.442208 299372544 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_iHhziB/credential'
> I0128 12:20:27.442344 299372544 slave.cpp:323] Slave using credential for:
> test-principal
> I0128 12:20:27.442428 299372544 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0128 12:20:27.443301 299372544 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0128 12:20:27.443349 299372544 slave.cpp:471] Slave attributes: [ ]
> I0128 12:20:27.443361 299372544 slave.cpp:476] Slave hostname: alexr.fritz.box
> I0128 12:20:27.443904 298835968 state.cpp:58] Recovering state from
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_iHhziB/meta'
> I0128 12:20:27.444108 297226240 status_update_manager.cpp:200] Recovering
> status update manager
> I0128 12:20:27.444362 300982272 containerizer.cpp:390] Recovering
> containerizer
> I0128 12:20:27.446213 297226240 provisioner.cpp:245] Provisioner recovery
> complete
> I0128 12:20:27.446542 297226240 slave.cpp:4495] Finished recovery
> I0128 12:20:27.447430 297226240 slave.cpp:4667] Querying resource estimator
> for oversubscribable resources
> I0128 12:20:27.447684 300445696 status_update_manager.cpp:174] Pausing
> sending status updates
> I0128 12:20:27.447726 297226240 slave.cpp:795] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.447760 297226240 slave.cpp:858] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.447773 297226240 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.448114 297762816 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.448084 297226240 slave.cpp:831] Detecting new master
> I0128 12:20:27.448473 297226240 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0128 12:20:27.448545 300982272 master.cpp:5521] Authenticating
> slave(870)@192.168.178.24:51278
> I0128 12:20:27.449328 297762816 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1737)@192.168.178.24:51278
> I0128 12:20:27.449581 298299392 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.449713 300982272 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.449743 300982272 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.449923 297762816 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.449990 297762816 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.450142 300445696 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.450389 300982272 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.450413 300982272 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.450489 300982272 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.450513 300982272 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.450531 300982272 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.450558 300982272 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.451807 300982272 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.451854 300982272 authenticator.cpp:317] Authentication success
> I0128 12:20:27.451932 298299392 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.452075 298835968 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(870)@192.168.178.24:51278
> I0128 12:20:27.452178 297762816 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1737)@192.168.178.24:51278
> I0128 12:20:27.452294 298299392 slave.cpp:926] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.452376 298299392 slave.cpp:1320] Will retry registration in
> 15.028781ms if necessary
> I0128 12:20:27.452481 297226240 master.cpp:4235] Registering slave at
> slave(870)@192.168.178.24:51278 (alexr.fritz.box) with id
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2
> I0128 12:20:27.452783 298299392 registrar.cpp:439] Applied 1 operations in
> 86us; attempting to update the 'registry'
> I0128 12:20:27.455883 298299392 log.cpp:683] Attempting to append 696 bytes
> to the log
> I0128 12:20:27.455989 299909120 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 7
> I0128 12:20:27.456845 300445696 replica.cpp:537] Replica received write
> request for position 7 from (18262)@192.168.178.24:51278
> I0128 12:20:27.457120 300445696 leveldb.cpp:341] Persisting action (715
> bytes) to leveldb took 276us
> I0128 12:20:27.457268 300445696 replica.cpp:712] Persisted action at 7
> I0128 12:20:27.459020 298835968 replica.cpp:691] Replica received learned
> notice for position 7 from @0.0.0.0:0
> I0128 12:20:27.459255 298835968 leveldb.cpp:341] Persisting action (717
> bytes) to leveldb took 210us
> I0128 12:20:27.459290 298835968 replica.cpp:712] Persisted action at 7
> I0128 12:20:27.459307 298835968 replica.cpp:697] Replica learned APPEND
> action at position 7
> I0128 12:20:27.467411 299372544 registrar.cpp:484] Successfully updated the
> 'registry' in 12.083968ms
> I0128 12:20:27.467475 300982272 log.cpp:702] Attempting to truncate the log
> to 7
> I0128 12:20:27.467695 297226240 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 8
> I0128 12:20:27.467697 300982272 slave.cpp:1320] Will retry registration in
> 16.052253ms if necessary
> I0128 12:20:27.468121 297762816 slave.cpp:3435] Received ping from
> slave-observer(870)@192.168.178.24:51278
> I0128 12:20:27.468437 299909120 master.cpp:4303] Registered slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 at slave(870)@192.168.178.24:51278
> (alexr.fritz.box) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0128 12:20:27.468613 297226240 replica.cpp:537] Replica received write
> request for position 8 from (18263)@192.168.178.24:51278
> I0128 12:20:27.468813 298299392 hierarchical.cpp:473] Added slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 (alexr.fritz.box) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0128 12:20:27.469081 297226240 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 230us
> I0128 12:20:27.469113 297226240 replica.cpp:712] Persisted action at 8
> I0128 12:20:27.469173 299909120 master.cpp:4205] Slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 at slave(870)@192.168.178.24:51278
> (alexr.fritz.box) already registered, resending acknowledgement
> I0128 12:20:27.469702 298299392 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.470820 298299392 hierarchical.cpp:1116] Performed allocation
> for slave bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 in 1920us
> I0128 12:20:27.471000 299372544 slave.cpp:970] Registered with master
> master@192.168.178.24:51278; given slave ID
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2
> I0128 12:20:27.471022 299372544 fetcher.cpp:81] Clearing fetcher cache
> I0128 12:20:27.471740 299372544 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterQuotaTest_AvailableResourcesAfterRescinding_iHhziB/meta/slaves/bd6f3479-18eb-478d-8a08-a41364ecbd05-S2/slave.info'
> I0128 12:20:27.471943 297762816 status_update_manager.cpp:181] Resuming
> sending status updates
> I0128 12:20:27.472684 298835968 replica.cpp:691] Replica received learned
> notice for position 8 from @0.0.0.0:0
> I0128 12:20:27.472903 298835968 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 201us
> I0128 12:20:27.472951 298835968 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 27us
> I0128 12:20:27.472970 298835968 replica.cpp:712] Persisted action at 8
> I0128 12:20:27.473085 299372544 slave.cpp:1029] Forwarding total
> oversubscribed resources
> I0128 12:20:27.473274 298835968 replica.cpp:697] Replica learned TRUNCATE
> action at position 8
> W0128 12:20:27.473520 299372544 slave.cpp:1015] Already registered with
> master master@192.168.178.24:51278
> I0128 12:20:27.473541 299372544 slave.cpp:1029] Forwarding total
> oversubscribed resources
> I0128 12:20:27.473604 297226240 master.cpp:4644] Received update of slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 at slave(870)@192.168.178.24:51278
> (alexr.fritz.box) with total oversubscribed resources
> I0128 12:20:27.473798 297226240 master.cpp:4644] Received update of slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 at slave(870)@192.168.178.24:51278
> (alexr.fritz.box) with total oversubscribed resources
> I0128 12:20:27.473970 300982272 hierarchical.cpp:531] Slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 (alexr.fritz.box) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0128 12:20:27.474051 300982272 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.474071 300982272 hierarchical.cpp:1116] Performed allocation
> for slave bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 in 74us
> I0128 12:20:27.474261 300982272 hierarchical.cpp:531] Slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 (alexr.fritz.box) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0128 12:20:27.474347 300982272 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.474370 300982272 hierarchical.cpp:1116] Performed allocation
> for slave bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 in 69us
> I0128 12:20:27.476686 2080858880 sched.cpp:222] Version: 0.28.0
> I0128 12:20:27.477182 299372544 sched.cpp:326] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.477264 299372544 sched.cpp:382] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.477284 299372544 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.477462 298835968 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.477645 298299392 master.cpp:5521] Authenticating
> scheduler-5f6db5d6-b088-4d13-a14c-94734bb39bf7@192.168.178.24:51278
> I0128 12:20:27.477763 299909120 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1738)@192.168.178.24:51278
> I0128 12:20:27.477926 298299392 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.478040 300982272 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.478076 300982272 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.478152 298299392 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.478196 298299392 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.478247 298299392 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.478337 299909120 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.478356 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.478369 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.478392 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.478462 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.478478 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.478487 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.478502 299909120 authenticator.cpp:317] Authentication success
> I0128 12:20:27.478562 300982272 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.478618 297226240 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-5f6db5d6-b088-4d13-a14c-94734bb39bf7@192.168.178.24:51278
> I0128 12:20:27.478713 298835968 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1738)@192.168.178.24:51278
> I0128 12:20:27.478826 297762816 sched.cpp:471] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.478871 297762816 sched.cpp:780] Sending SUBSCRIBE call to
> master@192.168.178.24:51278
> I0128 12:20:27.478971 297762816 sched.cpp:813] Will retry registration in
> 250.550205ms if necessary
> I0128 12:20:27.479032 298835968 master.cpp:2278] Received SUBSCRIBE call for
> framework 'framework(18264)' at
> scheduler-5f6db5d6-b088-4d13-a14c-94734bb39bf7@192.168.178.24:51278
> W0128 12:20:27.479054 298835968 master.cpp:2285] Framework at
> scheduler-5f6db5d6-b088-4d13-a14c-94734bb39bf7@192.168.178.24:51278
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I0128 12:20:27.479069 298835968 master.cpp:1749] Authorizing framework
> principal '' to receive offers for role 'role1'
> I0128 12:20:27.479228 298835968 master.cpp:2349] Subscribing framework
> framework(18264) with checkpointing disabled and capabilities [ ]
> I0128 12:20:27.479449 300445696 hierarchical.cpp:265] Added framework
> framework(18264)
> I0128 12:20:27.479570 298299392 sched.cpp:707] Framework registered with
> framework(18264)
> I0128 12:20:27.479625 298299392 sched.cpp:721] Scheduler::registered took 45us
> W0128 12:20:27.479655 297226240 slave.cpp:2236] Ignoring updating pid for
> framework framework(18264) because it does not exist
> W0128 12:20:27.479701 297762816 slave.cpp:2236] Ignoring updating pid for
> framework framework(18264) because it does not exist
> W0128 12:20:27.479756 297226240 slave.cpp:2236] Ignoring updating pid for
> framework framework(18264) because it does not exist
> I0128 12:20:27.480363 300445696 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.480406 300445696 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 948us
> I0128 12:20:27.480887 300982272 master.cpp:5350] Sending 3 offers to
> framework framework(18264) (framework(18264)) at
> scheduler-5f6db5d6-b088-4d13-a14c-94734bb39bf7@192.168.178.24:51278
> I0128 12:20:27.481411 299909120 sched.cpp:877] Scheduler::resourceOffers took
> 180us
> I0128 12:20:27.485344 300445696 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.485376 300445696 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.485397 300445696 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 135us
> I0128 12:20:27.486169 2080858880 sched.cpp:222] Version: 0.28.0
> I0128 12:20:27.486497 300445696 sched.cpp:326] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.486548 300445696 sched.cpp:382] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.486562 300445696 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.486661 299909120 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.486810 297226240 master.cpp:5521] Authenticating
> scheduler-ee0b23b6-ac62-4d64-86ce-daf6a4e30f92@192.168.178.24:51278
> I0128 12:20:27.486898 300982272 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1739)@192.168.178.24:51278
> I0128 12:20:27.487023 299909120 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.487139 297762816 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.487190 297762816 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.487296 300445696 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.487432 300445696 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.487490 300982272 authenticatee.cpp:258] Received SASL
> authentication step
> I0128 12:20:27.488359 299909120 authenticator.cpp:231] Received SASL
> authentication step
> I0128 12:20:27.488391 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.488405 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.488428 299909120 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.488445 299909120 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.488471 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.488481 299909120 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.488507 2080858880 sched.cpp:222] Version: 0.28.0
> I0128 12:20:27.488694 299909120 authenticator.cpp:317] Authentication success
> I0128 12:20:27.488770 300445696 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.488823 298299392 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-ee0b23b6-ac62-4d64-86ce-daf6a4e30f92@192.168.178.24:51278
> I0128 12:20:27.488911 298835968 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1739)@192.168.178.24:51278
> I0128 12:20:27.489013 298299392 sched.cpp:326] New master detected at
> master@192.168.178.24:51278
> I0128 12:20:27.489037 297762816 sched.cpp:471] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.489061 297762816 sched.cpp:780] Sending SUBSCRIBE call to
> master@192.168.178.24:51278
> I0128 12:20:27.489102 298299392 sched.cpp:382] Authenticating with master
> master@192.168.178.24:51278
> I0128 12:20:27.489122 298299392 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0128 12:20:27.489151 297762816 sched.cpp:813] Will retry registration in
> 955.991763ms if necessary
> I0128 12:20:27.489215 299909120 master.cpp:2278] Received SUBSCRIBE call for
> framework 'framework(18265)' at
> scheduler-ee0b23b6-ac62-4d64-86ce-daf6a4e30f92@192.168.178.24:51278
> W0128 12:20:27.489248 299909120 master.cpp:2285] Framework at
> scheduler-ee0b23b6-ac62-4d64-86ce-daf6a4e30f92@192.168.178.24:51278
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I0128 12:20:27.489266 299909120 master.cpp:1749] Authorizing framework
> principal '' to receive offers for role 'role2'
> I0128 12:20:27.489315 297762816 authenticatee.cpp:121] Creating new client
> SASL connection
> I0128 12:20:27.489439 299909120 master.cpp:5521] Authenticating
> scheduler-a5c3a776-b3e5-42dc-a9fa-63686dca3249@192.168.178.24:51278
> I0128 12:20:27.489513 299372544 authenticator.cpp:413] Starting
> authentication session for crammd5_authenticatee(1740)@192.168.178.24:51278
> I0128 12:20:27.489545 299909120 master.cpp:2349] Subscribing framework
> framework(18265) with checkpointing disabled and capabilities [ ]
> I0128 12:20:27.489681 298835968 authenticator.cpp:98] Creating new server
> SASL connection
> I0128 12:20:27.489807 298299392 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0128 12:20:27.489835 298299392 authenticatee.cpp:238] Attempting to
> authenticate with mechanism 'CRAM-MD5'
> I0128 12:20:27.489869 299372544 hierarchical.cpp:265] Added framework
> framework(18265)
> I0128 12:20:27.489958 298299392 authenticator.cpp:203] Received SASL
> authentication start
> I0128 12:20:27.489969 297762816 sched.cpp:707] Framework registered with
> framework(18265)
> I0128 12:20:27.489982 299372544 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.490000 298299392 authenticator.cpp:325] Authentication
> requires more steps
> I0128 12:20:27.490015 299372544 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.490034 299372544 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 151us
> I0128 12:20:27.490067 297762816 sched.cpp:721] Scheduler::registered took 92us
> W0128 12:20:27.490088 300445696 slave.cpp:2236] Ignoring updating pid for
> framework framework(18265) because it does not exist
> I0128 12:20:27.490102 297226240 authenticatee.cpp:258] Received SASL
> authentication step
> W0128 12:20:27.490145 298299392 slave.cpp:2236] Ignoring updating pid for
> framework framework(18265) because it does not exist
> I0128 12:20:27.490262 300445696 authenticator.cpp:231] Received SASL
> authentication step
> W0128 12:20:27.490279 298299392 slave.cpp:2236] Ignoring updating pid for
> framework framework(18265) because it does not exist
> I0128 12:20:27.490291 300445696 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0128 12:20:27.490304 300445696 auxprop.cpp:179] Looking up auxiliary
> property '*userPassword'
> I0128 12:20:27.490324 300445696 auxprop.cpp:179] Looking up auxiliary
> property '*cmusaslsecretCRAM-MD5'
> I0128 12:20:27.490341 300445696 auxprop.cpp:107] Request to lookup properties
> for user: 'test-principal' realm: 'alexr.fritz.box' server FQDN:
> 'alexr.fritz.box' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
> SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0128 12:20:27.490352 300445696 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.490362 300445696 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0128 12:20:27.490375 300445696 authenticator.cpp:317] Authentication success
> I0128 12:20:27.490464 299372544 authenticatee.cpp:298] Authentication success
> I0128 12:20:27.490517 297226240 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-a5c3a776-b3e5-42dc-a9fa-63686dca3249@192.168.178.24:51278
> I0128 12:20:27.490598 299909120 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(1740)@192.168.178.24:51278
> I0128 12:20:27.490722 298299392 sched.cpp:471] Successfully authenticated
> with master master@192.168.178.24:51278
> I0128 12:20:27.490741 298299392 sched.cpp:780] Sending SUBSCRIBE call to
> master@192.168.178.24:51278
> I0128 12:20:27.490811 298299392 sched.cpp:813] Will retry registration in
> 922.212316ms if necessary
> I0128 12:20:27.490871 300982272 master.cpp:2278] Received SUBSCRIBE call for
> framework 'framework(18266)' at
> scheduler-a5c3a776-b3e5-42dc-a9fa-63686dca3249@192.168.178.24:51278
> W0128 12:20:27.490893 300982272 master.cpp:2285] Framework at
> scheduler-a5c3a776-b3e5-42dc-a9fa-63686dca3249@192.168.178.24:51278
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I0128 12:20:27.490907 300982272 master.cpp:1749] Authorizing framework
> principal '' to receive offers for role 'role2'
> I0128 12:20:27.491086 299909120 master.cpp:2349] Subscribing framework
> framework(18266) with checkpointing disabled and capabilities [ ]
> I0128 12:20:27.491291 297226240 hierarchical.cpp:265] Added framework
> framework(18266)
> I0128 12:20:27.491345 300445696 sched.cpp:707] Framework registered with
> framework(18266)
> I0128 12:20:27.491374 297226240 hierarchical.cpp:1403] No resources available
> to allocate!
> W0128 12:20:27.491379 300982272 slave.cpp:2236] Ignoring updating pid for
> framework framework(18266) because it does not exist
> I0128 12:20:27.491402 297226240 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.491418 297226240 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 116us
> I0128 12:20:27.491427 300445696 sched.cpp:721] Scheduler::registered took 73us
> W0128 12:20:27.491439 299372544 slave.cpp:2236] Ignoring updating pid for
> framework framework(18266) because it does not exist
> W0128 12:20:27.491523 297762816 slave.cpp:2236] Ignoring updating pid for
> framework framework(18266) because it does not exist
> I0128 12:20:27.491674 2080858880 resources.cpp:564] Parsing resources as JSON
> failed: cpus:1;mem:512
> Trying semicolon-delimited string format instead
> I0128 12:20:27.493041 297226240 process.cpp:3141] Handling HTTP event for
> process 'master' with path: '/master/quota'
> I0128 12:20:27.493536 299909120 http.cpp:503] HTTP POST for /master/quota
> from 192.168.178.24:51640
> I0128 12:20:27.493561 299909120 quota_handler.cpp:211] Setting quota from
> request:
> '{"force":false,"guarantee":[{"name":"cpus","role":"*","scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","role":"*","scalar":{"value":512.0},"type":"SCALAR"}],"role":"role2"}'
> I0128 12:20:27.493954 299909120 quota_handler.cpp:446] Authorizing principal
> 'test-principal' to request quota for role 'role2'
> I0128 12:20:27.494176 299909120 quota_handler.cpp:70] Performing capacity
> heuristic check for a set quota request
> I0128 12:20:27.494499 300445696 registrar.cpp:439] Applied 1 operations in
> 80us; attempting to update the 'registry'
> I0128 12:20:27.494951 297226240 log.cpp:683] Attempting to append 770 bytes
> to the log
> I0128 12:20:27.495055 298299392 coordinator.cpp:348] Coordinator attempting
> to write APPEND action at position 9
> I0128 12:20:27.495833 297226240 replica.cpp:537] Replica received write
> request for position 9 from (18269)@192.168.178.24:51278
> I0128 12:20:27.496049 297226240 leveldb.cpp:341] Persisting action (789
> bytes) to leveldb took 197us
> I0128 12:20:27.496085 297226240 replica.cpp:712] Persisted action at 9
> I0128 12:20:27.496620 298835968 replica.cpp:691] Replica received learned
> notice for position 9 from @0.0.0.0:0
> I0128 12:20:27.496810 298835968 leveldb.cpp:341] Persisting action (791
> bytes) to leveldb took 177us
> I0128 12:20:27.496841 298835968 replica.cpp:712] Persisted action at 9
> I0128 12:20:27.496857 298835968 replica.cpp:697] Replica learned APPEND
> action at position 9
> I0128 12:20:27.498211 300445696 registrar.cpp:484] Successfully updated the
> 'registry' in 3.668992ms
> I0128 12:20:27.498492 300982272 log.cpp:702] Attempting to truncate the log
> to 9
> I0128 12:20:27.498584 298835968 coordinator.cpp:348] Coordinator attempting
> to write TRUNCATE action at position 10
> I0128 12:20:27.498679 298299392 hierarchical.cpp:1024] Set quota cpus(*):1;
> mem(*):512 for role 'role2'
> I0128 12:20:27.499006 300982272 sched.cpp:903] Rescinded offer
> bd6f3479-18eb-478d-8a08-a41364ecbd05-O2
> I0128 12:20:27.499060 300982272 sched.cpp:914] Scheduler::offerRescinded took
> 34us
> I0128 12:20:27.499174 298299392 hierarchical.cpp:1403] No resources available
> to allocate!
> I0128 12:20:27.499207 298299392 hierarchical.cpp:1498] No inverse offers to
> send out!
> I0128 12:20:27.499222 299372544 replica.cpp:537] Replica received write
> request for position 10 from (18270)@192.168.178.24:51278
> I0128 12:20:27.499229 298299392 hierarchical.cpp:1096] Performed allocation
> for 3 slaves in 516us
> I0128 12:20:27.499322 300445696 sched.cpp:903] Rescinded offer
> bd6f3479-18eb-478d-8a08-a41364ecbd05-O1
> I0128 12:20:27.499373 300445696 sched.cpp:914] Scheduler::offerRescinded took
> 35us
> I0128 12:20:27.499429 299372544 leveldb.cpp:341] Persisting action (16 bytes)
> to leveldb took 194us
> I0128 12:20:27.499469 299372544 replica.cpp:712] Persisted action at 10
> I0128 12:20:27.499477 298299392 hierarchical.cpp:892] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2 from framework framework(18264)
> I0128 12:20:27.499708 298299392 hierarchical.cpp:892] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1 from framework framework(18264)
> I0128 12:20:27.500056 299909120 replica.cpp:691] Replica received learned
> notice for position 10 from @0.0.0.0:0
> I0128 12:20:27.500241 299909120 leveldb.cpp:341] Persisting action (18 bytes)
> to leveldb took 175us
> I0128 12:20:27.500306 299909120 leveldb.cpp:399] Deleting ~2 keys from
> leveldb took 34us
> I0128 12:20:27.500331 299909120 replica.cpp:712] Persisted action at 10
> I0128 12:20:27.500358 299909120 replica.cpp:697] Replica learned TRUNCATE
> action at position 10
> I0128 12:20:27.501042 297226240 master.cpp:1025] Master terminating
> I0128 12:20:27.501637 298835968 hierarchical.cpp:505] Removed slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S2
> I0128 12:20:27.501849 300982272 hierarchical.cpp:505] Removed slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S1
> I0128 12:20:27.502151 300982272 hierarchical.cpp:505] Removed slave
> bd6f3479-18eb-478d-8a08-a41364ecbd05-S0
> I0128 12:20:27.502595 300982272 hierarchical.cpp:326] Removed framework
> framework(18266)
> I0128 12:20:27.502773 299909120 hierarchical.cpp:326] Removed framework
> framework(18265)
> I0128 12:20:27.503046 299909120 hierarchical.cpp:326] Removed framework
> framework(18264)
> I0128 12:20:27.503330 299372544 slave.cpp:3481] master@192.168.178.24:51278
> exited
> W0128 12:20:27.503353 299372544 slave.cpp:3484] Master disconnected! Waiting
> for a new master to be elected
> I0128 12:20:27.503422 299372544 slave.cpp:3481] master@192.168.178.24:51278
> exited
> W0128 12:20:27.503446 299372544 slave.cpp:3484] Master disconnected! Waiting
> for a new master to be elected
> I0128 12:20:27.503530 299372544 slave.cpp:3481] master@192.168.178.24:51278
> exited
> W0128 12:20:27.503548 299372544 slave.cpp:3484] Master disconnected! Waiting
> for a new master to be elected
> I0128 12:20:27.512778 2080858880 slave.cpp:667] Slave terminating
> I0128 12:20:27.515347 2080858880 slave.cpp:667] Slave terminating
> I0128 12:20:27.517685 2080858880 slave.cpp:667] Slave terminating
> [ OK ] MasterQuotaTest.AvailableResourcesAfterRescinding (205 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
