[
https://issues.apache.org/jira/browse/MESOS-4409?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15102634#comment-15102634
]
Greg Mann edited comment on MESOS-4409 at 1/15/16 10:58 PM:
------------------------------------------------------------
You could try introducing a {{Clock::settle()}} before you hit the state
endpoint to make sure the master is aware of all framework shutdowns first.
This will allow all existing scheduled work to complete before continuing.
was (Author: greggomann):
You could try introducing a {{Clock::settle()}} before you hit the state
endpoint to make sure the master is aware of all framework shutdowns first.
> MasterTest.MaxCompletedFrameworksFlag is flaky
> ----------------------------------------------
>
> Key: MESOS-4409
> URL: https://issues.apache.org/jira/browse/MESOS-4409
> Project: Mesos
> Issue Type: Bug
> Components: master, tests
> Affects Versions: 0.26.0
> Environment: On Jenkins CI: gcc,--verbose,ubuntu:14.04,docker
> Reporter: Greg Mann
> Labels: flaky-test, mesosphere, tests
>
> Saw this failure on Jenkins CI:
> {code}
> [ RUN ] MasterTest.MaxCompletedFrameworksFlag
> I0115 21:24:50.344116 31507 leveldb.cpp:174] Opened db in 2.062201ms
> I0115 21:24:50.344874 31507 leveldb.cpp:181] Compacted db in 716863ns
> I0115 21:24:50.344923 31507 leveldb.cpp:196] Created db iterator in 19087ns
> I0115 21:24:50.344949 31507 leveldb.cpp:202] Seeked to beginning of db in
> 1897ns
> I0115 21:24:50.344965 31507 leveldb.cpp:271] Iterated through 0 keys in the
> db in 298ns
> I0115 21:24:50.345012 31507 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0115 21:24:50.345432 31536 recover.cpp:447] Starting replica recovery
> I0115 21:24:50.345657 31536 recover.cpp:473] Replica is in EMPTY status
> I0115 21:24:50.346535 31539 replica.cpp:673] Replica in EMPTY status received
> a broadcasted recover request from (6089)@172.17.0.4:52665
> I0115 21:24:50.347028 31540 recover.cpp:193] Received a recover response from
> a replica in EMPTY status
> I0115 21:24:50.347554 31526 recover.cpp:564] Updating replica status to
> STARTING
> I0115 21:24:50.348175 31540 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 433937ns
> I0115 21:24:50.348215 31526 master.cpp:374] Master
> bf6ba047-245f-4e65-986c-1880cef81248 (4e6fbf10d387) started on
> 172.17.0.4:52665
> I0115 21:24:50.349417 31540 replica.cpp:320] Persisted replica status to
> STARTING
> I0115 21:24:50.349630 31536 recover.cpp:473] Replica is in STARTING status
> I0115 21:24:50.349421 31526 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/2wURTY/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="0"
> --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"
> --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui"
> --work_dir="/tmp/2wURTY/master" --zk_session_timeout="10secs"
> I0115 21:24:50.349720 31526 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0115 21:24:50.349737 31526 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0115 21:24:50.349750 31526 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/2wURTY/credentials'
> I0115 21:24:50.350005 31526 master.cpp:466] Using default 'crammd5'
> authenticator
> I0115 21:24:50.350132 31526 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0115 21:24:50.350256 31526 master.cpp:569] Authorization enabled
> I0115 21:24:50.350546 31529 hierarchical.cpp:147] Initialized hierarchical
> allocator process
> I0115 21:24:50.350626 31536 whitelist_watcher.cpp:77] No whitelist given
> I0115 21:24:50.350559 31538 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (6090)@172.17.0.4:52665
> I0115 21:24:50.351049 31534 recover.cpp:193] Received a recover response from
> a replica in STARTING status
> I0115 21:24:50.351704 31537 recover.cpp:564] Updating replica status to VOTING
> I0115 21:24:50.352221 31532 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 322228ns
> I0115 21:24:50.352246 31532 replica.cpp:320] Persisted replica status to
> VOTING
> I0115 21:24:50.352371 31541 recover.cpp:578] Successfully joined the Paxos
> group
> I0115 21:24:50.352620 31541 recover.cpp:462] Recover process terminated
> I0115 21:24:50.353121 31528 master.cpp:1710] The newly elected leader is
> [email protected]:52665 with id bf6ba047-245f-4e65-986c-1880cef81248
> I0115 21:24:50.353152 31528 master.cpp:1723] Elected as the leading master!
> I0115 21:24:50.353173 31528 master.cpp:1468] Recovering from registrar
> I0115 21:24:50.353307 31527 registrar.cpp:307] Recovering registrar
> I0115 21:24:50.354140 31532 log.cpp:659] Attempting to start the writer
> I0115 21:24:50.355285 31533 replica.cpp:493] Replica received implicit
> promise request from (6092)@172.17.0.4:52665 with proposal 1
> I0115 21:24:50.355602 31533 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 287571ns
> I0115 21:24:50.355624 31533 replica.cpp:342] Persisted promised to 1
> I0115 21:24:50.356180 31529 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0115 21:24:50.357229 31534 replica.cpp:388] Replica received explicit
> promise request from (6093)@172.17.0.4:52665 for position 0 with proposal 2
> I0115 21:24:50.357585 31534 leveldb.cpp:341] Persisting action (8 bytes) to
> leveldb took 315117ns
> I0115 21:24:50.357609 31534 replica.cpp:712] Persisted action at 0
> I0115 21:24:50.358548 31539 replica.cpp:537] Replica received write request
> for position 0 from (6094)@172.17.0.4:52665
> I0115 21:24:50.358669 31539 leveldb.cpp:436] Reading position from leveldb
> took 27690ns
> I0115 21:24:50.359011 31539 leveldb.cpp:341] Persisting action (14 bytes) to
> leveldb took 284908ns
> I0115 21:24:50.359035 31539 replica.cpp:712] Persisted action at 0
> I0115 21:24:50.359598 31528 replica.cpp:691] Replica received learned notice
> for position 0 from @0.0.0.0:0
> I0115 21:24:50.360041 31528 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 280673ns
> I0115 21:24:50.360077 31528 replica.cpp:712] Persisted action at 0
> I0115 21:24:50.360105 31528 replica.cpp:697] Replica learned NOP action at
> position 0
> I0115 21:24:50.360677 31530 log.cpp:675] Writer started with ending position 0
> I0115 21:24:50.361670 31538 leveldb.cpp:436] Reading position from leveldb
> took 22320ns
> I0115 21:24:50.362578 31538 registrar.cpp:340] Successfully fetched the
> registry (0B) in 9.231104ms
> I0115 21:24:50.362691 31538 registrar.cpp:439] Applied 1 operations in
> 33642ns; attempting to update the 'registry'
> I0115 21:24:50.363369 31534 log.cpp:683] Attempting to append 170 bytes to
> the log
> I0115 21:24:50.363525 31539 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0115 21:24:50.364259 31539 replica.cpp:537] Replica received write request
> for position 1 from (6095)@172.17.0.4:52665
> I0115 21:24:50.364629 31539 leveldb.cpp:341] Persisting action (189 bytes) to
> leveldb took 338021ns
> I0115 21:24:50.364653 31539 replica.cpp:712] Persisted action at 1
> I0115 21:24:50.365277 31537 replica.cpp:691] Replica received learned notice
> for position 1 from @0.0.0.0:0
> I0115 21:24:50.365600 31537 leveldb.cpp:341] Persisting action (191 bytes) to
> leveldb took 292631ns
> I0115 21:24:50.365627 31537 replica.cpp:712] Persisted action at 1
> I0115 21:24:50.365650 31537 replica.cpp:697] Replica learned APPEND action at
> position 1
> I0115 21:24:50.366526 31529 registrar.cpp:484] Successfully updated the
> 'registry' in 3.780864ms
> I0115 21:24:50.366664 31529 registrar.cpp:370] Successfully recovered
> registrar
> I0115 21:24:50.366803 31533 log.cpp:702] Attempting to truncate the log to 1
> I0115 21:24:50.367010 31534 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0115 21:24:50.367450 31530 hierarchical.cpp:165] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0115 21:24:50.367632 31539 master.cpp:1520] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I0115 21:24:50.367905 31527 replica.cpp:537] Replica received write request
> for position 2 from (6096)@172.17.0.4:52665
> I0115 21:24:50.368221 31527 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 277782ns
> I0115 21:24:50.368242 31527 replica.cpp:712] Persisted action at 2
> I0115 21:24:50.368863 31527 replica.cpp:691] Replica received learned notice
> for position 2 from @0.0.0.0:0
> I0115 21:24:50.369180 31527 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 286751ns
> I0115 21:24:50.369227 31527 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 23761ns
> I0115 21:24:50.369251 31527 replica.cpp:712] Persisted action at 2
> I0115 21:24:50.369268 31527 replica.cpp:697] Replica learned TRUNCATE action
> at position 2
> I0115 21:24:50.380362 31507 containerizer.cpp:140] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> W0115 21:24:50.380955 31507 backend.cpp:48] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0115 21:24:50.383384 31540 slave.cpp:191] Slave started on
> 179)@172.17.0.4:52665
> I0115 21:24:50.383417 31540 slave.cpp:192] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
> --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
> --cgroups_root="mesos" --container_disk_watch_interval="15secs"
> --containerizers="mesos"
> --credential="/tmp/MasterTest_MaxCompletedFrameworksFlag_LW3xM9/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/MasterTest_MaxCompletedFrameworksFlag_LW3xM9/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --oversubscribed_resources_interval="15secs"
> --perf_duration="10secs" --perf_interval="1mins"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/MasterTest_MaxCompletedFrameworksFlag_LW3xM9"
> I0115 21:24:50.383783 31540 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_LW3xM9/credential'
> I0115 21:24:50.383944 31540 slave.cpp:322] Slave using credential for:
> test-principal
> I0115 21:24:50.384098 31540 resources.cpp:482] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0115 21:24:50.384475 31540 slave.cpp:392] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0115 21:24:50.384555 31540 slave.cpp:400] Slave attributes: [ ]
> I0115 21:24:50.384567 31540 slave.cpp:405] Slave hostname: 4e6fbf10d387
> I0115 21:24:50.385574 31536 state.cpp:58] Recovering state from
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_LW3xM9/meta'
> I0115 21:24:50.385599 31507 sched.cpp:164] Version: 0.27.0
> I0115 21:24:50.386801 31536 status_update_manager.cpp:200] Recovering status
> update manager
> I0115 21:24:50.387008 31529 sched.cpp:268] New master detected at
> [email protected]:52665
> I0115 21:24:50.387040 31536 containerizer.cpp:386] Recovering containerizer
> I0115 21:24:50.387125 31529 sched.cpp:324] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.387145 31529 sched.cpp:331] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.387645 31539 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.387882 31536 master.cpp:5521] Authenticating
> [email protected]:52665
> I0115 21:24:50.387997 31541 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(418)@172.17.0.4:52665
> I0115 21:24:50.388212 31533 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.388444 31534 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.388481 31534 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.388574 31534 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.388635 31534 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.388684 31531 provisioner.cpp:245] Provisioner recovery complete
> I0115 21:24:50.388734 31534 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.389030 31533 slave.cpp:4424] Finished recovery
> I0115 21:24:50.389489 31532 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.389499 31533 slave.cpp:4596] Querying resource estimator for
> oversubscribable resources
> I0115 21:24:50.389519 31532 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.389529 31532 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.389565 31532 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.389585 31532 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.389592 31532 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.389597 31532 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.389611 31532 authenticator.cpp:317] Authentication success
> I0115 21:24:50.389681 31537 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.389813 31540 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> [email protected]:52665
> I0115 21:24:50.389847 31526 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(418)@172.17.0.4:52665
> I0115 21:24:50.390035 31539 sched.cpp:413] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.390059 31539 sched.cpp:722] Sending SUBSCRIBE call to
> [email protected]:52665
> I0115 21:24:50.390141 31539 sched.cpp:755] Will retry registration in
> 1.88913061secs if necessary
> I0115 21:24:50.390153 31533 slave.cpp:724] New master detected at
> [email protected]:52665
> I0115 21:24:50.390224 31537 status_update_manager.cpp:174] Pausing sending
> status updates
> I0115 21:24:50.390254 31532 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:52665
> I0115 21:24:50.390305 31533 slave.cpp:787] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.390341 31532 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0115 21:24:50.390480 31533 slave.cpp:792] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.391505 31533 slave.cpp:760] Detecting new master
> I0115 21:24:50.391538 31541 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.391604 31539 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0115 21:24:50.391634 31533 slave.cpp:4610] Received oversubscribable
> resources from the resource estimator
> I0115 21:24:50.391985 31528 hierarchical.cpp:259] Added framework
> bf6ba047-245f-4e65-986c-1880cef81248-0000
> I0115 21:24:50.392050 31528 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.392092 31528 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.392107 31531 sched.cpp:649] Framework registered with
> bf6ba047-245f-4e65-986c-1880cef81248-0000
> I0115 21:24:50.392124 31528 hierarchical.cpp:1079] Performed allocation for 0
> slaves in 114393ns
> I0115 21:24:50.392137 31539 master.cpp:5521] Authenticating
> slave(179)@172.17.0.4:52665
> I0115 21:24:50.392184 31531 sched.cpp:663] Scheduler::registered took 50817ns
> I0115 21:24:50.392218 31540 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(419)@172.17.0.4:52665
> I0115 21:24:50.392449 31507 sched.cpp:1851] Asked to stop the driver
> I0115 21:24:50.392616 31534 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.392640 31540 sched.cpp:1089] Stopping framework
> 'bf6ba047-245f-4e65-986c-1880cef81248-0000'
> I0115 21:24:50.392865 31527 master.cpp:5921] Processing TEARDOWN call for
> framework bf6ba047-245f-4e65-986c-1880cef81248-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.392902 31527 master.cpp:5933] Removing framework
> bf6ba047-245f-4e65-986c-1880cef81248-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.392935 31531 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.392976 31531 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.393277 31539 hierarchical.cpp:369] Deactivated framework
> bf6ba047-245f-4e65-986c-1880cef81248-0000
> I0115 21:24:50.393311 31534 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.393543 31534 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.393622 31538 hierarchical.cpp:320] Removed framework
> bf6ba047-245f-4e65-986c-1880cef81248-0000
> I0115 21:24:50.393787 31538 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.393990 31539 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.394024 31539 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.394038 31539 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.394076 31539 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.394105 31539 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.394119 31539 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.394129 31539 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.394145 31539 authenticator.cpp:317] Authentication success
> I0115 21:24:50.394242 31536 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.394295 31529 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(179)@172.17.0.4:52665
> I0115 21:24:50.394353 31539 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(419)@172.17.0.4:52665
> I0115 21:24:50.394626 31536 slave.cpp:855] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.394682 31507 sched.cpp:164] Version: 0.27.0
> I0115 21:24:50.394873 31536 slave.cpp:1249] Will retry registration in
> 13.811028ms if necessary
> I0115 21:24:50.395035 31528 master.cpp:4235] Registering slave at
> slave(179)@172.17.0.4:52665 (4e6fbf10d387) with id
> bf6ba047-245f-4e65-986c-1880cef81248-S0
> I0115 21:24:50.395550 31538 sched.cpp:268] New master detected at
> [email protected]:52665
> I0115 21:24:50.395658 31538 sched.cpp:324] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.395684 31538 sched.cpp:331] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.395666 31541 registrar.cpp:439] Applied 1 operations in
> 110346ns; attempting to update the 'registry'
> I0115 21:24:50.395959 31540 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.396792 31533 log.cpp:683] Attempting to append 339 bytes to
> the log
> I0115 21:24:50.396855 31538 master.cpp:5521] Authenticating
> [email protected]:52665
> I0115 21:24:50.396996 31540 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(420)@172.17.0.4:52665
> I0115 21:24:50.397105 31536 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 3
> I0115 21:24:50.397248 31540 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.397541 31526 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.397640 31526 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.397871 31526 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.397922 31526 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.398056 31532 replica.cpp:537] Replica received write request
> for position 3 from (6110)@172.17.0.4:52665
> I0115 21:24:50.398088 31526 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.398201 31536 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.398228 31536 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.398237 31536 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.398277 31536 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.398308 31536 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.398304 31532 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 206361ns
> I0115 21:24:50.398329 31536 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.398342 31536 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.398342 31532 replica.cpp:712] Persisted action at 3
> I0115 21:24:50.398368 31536 authenticator.cpp:317] Authentication success
> I0115 21:24:50.398480 31532 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.398583 31536 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(420)@172.17.0.4:52665
> I0115 21:24:50.398666 31535 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> [email protected]:52665
> I0115 21:24:50.399082 31529 sched.cpp:413] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.399107 31529 sched.cpp:722] Sending SUBSCRIBE call to
> [email protected]:52665
> I0115 21:24:50.399204 31529 sched.cpp:755] Will retry registration in
> 857.529667ms if necessary
> I0115 21:24:50.399314 31536 replica.cpp:691] Replica received learned notice
> for position 3 from @0.0.0.0:0
> I0115 21:24:50.399431 31529 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:52665
> I0115 21:24:50.399489 31529 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0115 21:24:50.399808 31532 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0115 21:24:50.399844 31536 leveldb.cpp:341] Persisting action (360 bytes) to
> leveldb took 498891ns
> I0115 21:24:50.399868 31536 replica.cpp:712] Persisted action at 3
> I0115 21:24:50.399885 31536 replica.cpp:697] Replica learned APPEND action at
> position 3
> I0115 21:24:50.400311 31533 hierarchical.cpp:259] Added framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001
> I0115 21:24:50.400454 31533 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.400485 31532 sched.cpp:649] Framework registered with
> bf6ba047-245f-4e65-986c-1880cef81248-0001
> I0115 21:24:50.400492 31533 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.400522 31533 hierarchical.cpp:1079] Performed allocation for 0
> slaves in 107405ns
> I0115 21:24:50.400563 31532 sched.cpp:663] Scheduler::registered took 55451ns
> I0115 21:24:50.400943 31507 sched.cpp:1851] Asked to stop the driver
> I0115 21:24:50.401514 31537 registrar.cpp:484] Successfully updated the
> 'registry' in 5.48608ms
> I0115 21:24:50.401751 31530 log.cpp:702] Attempting to truncate the log to 3
> I0115 21:24:50.402120 31537 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 4
> I0115 21:24:50.402757 31527 master.cpp:1211] Framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001 (default) at
> [email protected]:52665 disconnected
> I0115 21:24:50.402793 31527 master.cpp:2574] Disconnecting framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.402832 31527 master.cpp:2598] Deactivating framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.402916 31527 master.cpp:1235] Giving framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001 (default) at
> [email protected]:52665 0ns to
> failover
> I0115 21:24:50.403187 31540 hierarchical.cpp:369] Deactivated framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001
> I0115 21:24:50.403672 31535 replica.cpp:537] Replica received write request
> for position 4 from (6111)@172.17.0.4:52665
> I0115 21:24:50.404130 31538 slave.cpp:3366] Received ping from
> slave-observer(179)@172.17.0.4:52665
> I0115 21:24:50.404294 31535 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 585027ns
> I0115 21:24:50.404326 31535 replica.cpp:712] Persisted action at 4
> I0115 21:24:50.404701 31529 slave.cpp:899] Registered with master
> [email protected]:52665; given slave ID
> bf6ba047-245f-4e65-986c-1880cef81248-S0
> I0115 21:24:50.404803 31529 fetcher.cpp:81] Clearing fetcher cache
> I0115 21:24:50.404929 31539 hierarchical.cpp:465] Added slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 (4e6fbf10d387) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0115 21:24:50.405060 31535 status_update_manager.cpp:181] Resuming sending
> status updates
> I0115 21:24:50.405189 31539 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.405380 31529 slave.cpp:922] Checkpointing SlaveInfo to
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_LW3xM9/meta/slaves/bf6ba047-245f-4e65-986c-1880cef81248-S0/slave.info'
> I0115 21:24:50.404651 31527 master.cpp:4303] Registered slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 at slave(179)@172.17.0.4:52665
> (4e6fbf10d387) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0115 21:24:50.405262 31537 replica.cpp:691] Replica received learned notice
> for position 4 from @0.0.0.0:0
> I0115 21:24:50.405483 31527 master.cpp:5202] Framework failover timeout,
> removing framework bf6ba047-245f-4e65-986c-1880cef81248-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.405544 31539 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.405653 31527 master.cpp:5933] Removing framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.405707 31539 hierarchical.cpp:1101] Performed allocation for
> slave bf6ba047-245f-4e65-986c-1880cef81248-S0 in 734362ns
> I0115 21:24:50.405851 31529 slave.cpp:958] Forwarding total oversubscribed
> resources
> I0115 21:24:50.405922 31537 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 490775ns
> I0115 21:24:50.405946 31529 slave.cpp:2007] Asked to shut down framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001 by [email protected]:52665
> W0115 21:24:50.405972 31529 slave.cpp:2022] Cannot shut down unknown
> framework bf6ba047-245f-4e65-986c-1880cef81248-0001
> I0115 21:24:50.405984 31527 process.cpp:3141] Handling HTTP event for process
> 'master' with path: '/master/state'
> I0115 21:24:50.405992 31537 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 42432ns
> I0115 21:24:50.406016 31537 replica.cpp:712] Persisted action at 4
> I0115 21:24:50.406045 31537 replica.cpp:697] Replica learned TRUNCATE action
> at position 4
> I0115 21:24:50.406191 31529 hierarchical.cpp:320] Removed framework
> bf6ba047-245f-4e65-986c-1880cef81248-0001
> I0115 21:24:50.406347 31527 master.cpp:4644] Received update of slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 at slave(179)@172.17.0.4:52665
> (4e6fbf10d387) with total oversubscribed resources
> I0115 21:24:50.406702 31527 http.cpp:504] HTTP GET for /master/state from
> 172.17.0.4:47472
> I0115 21:24:50.407114 31529 hierarchical.cpp:521] Slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 (4e6fbf10d387) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0115 21:24:50.407284 31529 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.407315 31529 hierarchical.cpp:1101] Performed allocation for
> slave bf6ba047-245f-4e65-986c-1880cef81248-S0 in 159566ns
> I0115 21:24:50.410732 31539 slave.cpp:596] Slave terminating
> I0115 21:24:50.410933 31536 master.cpp:1172] Slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 at slave(179)@172.17.0.4:52665
> (4e6fbf10d387) disconnected
> I0115 21:24:50.411023 31536 master.cpp:2633] Disconnecting slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 at slave(179)@172.17.0.4:52665
> (4e6fbf10d387)
> I0115 21:24:50.411209 31536 master.cpp:2652] Deactivating slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 at slave(179)@172.17.0.4:52665
> (4e6fbf10d387)
> I0115 21:24:50.411339 31531 hierarchical.cpp:550] Slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0 deactivated
> I0115 21:24:50.413700 31535 master.cpp:1025] Master terminating
> I0115 21:24:50.414139 31536 hierarchical.cpp:496] Removed slave
> bf6ba047-245f-4e65-986c-1880cef81248-S0
> I0115 21:24:50.420747 31507 leveldb.cpp:174] Opened db in 2.230194ms
> I0115 21:24:50.422813 31507 leveldb.cpp:181] Compacted db in 2.036772ms
> I0115 21:24:50.422859 31507 leveldb.cpp:196] Created db iterator in 18158ns
> I0115 21:24:50.422894 31507 leveldb.cpp:202] Seeked to beginning of db in
> 18700ns
> I0115 21:24:50.423063 31507 leveldb.cpp:271] Iterated through 3 keys in the
> db in 125314ns
> I0115 21:24:50.423123 31507 replica.cpp:779] Replica recovered with log
> positions 3 -> 4 with 0 holes and 0 unlearned
> I0115 21:24:50.423527 31527 recover.cpp:447] Starting replica recovery
> I0115 21:24:50.423898 31531 recover.cpp:473] Replica is in VOTING status
> I0115 21:24:50.424299 31531 recover.cpp:462] Recover process terminated
> I0115 21:24:50.425678 31527 master.cpp:374] Master
> 2cfeb24a-de29-4273-8472-64f4f78e7791 (4e6fbf10d387) started on
> 172.17.0.4:52665
> I0115 21:24:50.425698 31527 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/2wURTY/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="1"
> --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"
> --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui"
> --work_dir="/tmp/2wURTY/master" --zk_session_timeout="10secs"
> I0115 21:24:50.425966 31527 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0115 21:24:50.425976 31527 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0115 21:24:50.425982 31527 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/2wURTY/credentials'
> I0115 21:24:50.426218 31527 master.cpp:466] Using default 'crammd5'
> authenticator
> I0115 21:24:50.426334 31527 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0115 21:24:50.426484 31527 master.cpp:569] Authorization enabled
> I0115 21:24:50.426738 31536 hierarchical.cpp:147] Initialized hierarchical
> allocator process
> I0115 21:24:50.426743 31534 whitelist_watcher.cpp:77] No whitelist given
> I0115 21:24:50.428192 31532 master.cpp:1710] The newly elected leader is
> [email protected]:52665 with id 2cfeb24a-de29-4273-8472-64f4f78e7791
> I0115 21:24:50.428226 31532 master.cpp:1723] Elected as the leading master!
> I0115 21:24:50.428247 31532 master.cpp:1468] Recovering from registrar
> I0115 21:24:50.428396 31538 registrar.cpp:307] Recovering registrar
> I0115 21:24:50.428988 31541 log.cpp:659] Attempting to start the writer
> I0115 21:24:50.430251 31532 replica.cpp:493] Replica received implicit
> promise request from (6118)@172.17.0.4:52665 with proposal 2
> I0115 21:24:50.431041 31532 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 751431ns
> I0115 21:24:50.431072 31532 replica.cpp:342] Persisted promised to 2
> I0115 21:24:50.431737 31538 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0115 21:24:50.432107 31531 log.cpp:675] Writer started with ending position 4
> I0115 21:24:50.433365 31535 leveldb.cpp:436] Reading position from leveldb
> took 68973ns
> I0115 21:24:50.433504 31535 leveldb.cpp:436] Reading position from leveldb
> took 50259ns
> I0115 21:24:50.435158 31539 registrar.cpp:340] Successfully fetched the
> registry (300B) in 6.672896ms
> I0115 21:24:50.435484 31539 registrar.cpp:439] Applied 1 operations in
> 64836ns; attempting to update the 'registry'
> I0115 21:24:50.436451 31540 log.cpp:683] Attempting to append 339 bytes to
> the log
> I0115 21:24:50.436666 31529 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 5
> I0115 21:24:50.437423 31527 replica.cpp:537] Replica received write request
> for position 5 from (6119)@172.17.0.4:52665
> I0115 21:24:50.437846 31527 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 385190ns
> I0115 21:24:50.437873 31527 replica.cpp:712] Persisted action at 5
> I0115 21:24:50.438668 31540 replica.cpp:691] Replica received learned notice
> for position 5 from @0.0.0.0:0
> I0115 21:24:50.439071 31540 leveldb.cpp:341] Persisting action (360 bytes) to
> leveldb took 347656ns
> I0115 21:24:50.439100 31540 replica.cpp:712] Persisted action at 5
> I0115 21:24:50.439124 31540 replica.cpp:697] Replica learned APPEND action at
> position 5
> I0115 21:24:50.440376 31536 registrar.cpp:484] Successfully updated the
> 'registry' in 4.820736ms
> I0115 21:24:50.440587 31536 registrar.cpp:370] Successfully recovered
> registrar
> I0115 21:24:50.440613 31532 log.cpp:702] Attempting to truncate the log to 5
> I0115 21:24:50.440734 31535 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 6
> I0115 21:24:50.441460 31536 replica.cpp:537] Replica received write request
> for position 6 from (6120)@172.17.0.4:52665
> I0115 21:24:50.441517 31530 master.cpp:1520] Recovered 1 slaves from the
> Registry (300B) ; allowing 10mins for slaves to re-register
> I0115 21:24:50.441542 31539 hierarchical.cpp:165] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0115 21:24:50.442030 31536 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 534862ns
> I0115 21:24:50.442054 31536 replica.cpp:712] Persisted action at 6
> I0115 21:24:50.442625 31529 replica.cpp:691] Replica received learned notice
> for position 6 from @0.0.0.0:0
> I0115 21:24:50.442999 31529 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 344836ns
> I0115 21:24:50.443058 31529 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 32653ns
> I0115 21:24:50.443085 31529 replica.cpp:712] Persisted action at 6
> I0115 21:24:50.443105 31529 replica.cpp:697] Replica learned TRUNCATE action
> at position 6
> I0115 21:24:50.454164 31507 containerizer.cpp:140] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> W0115 21:24:50.454710 31507 backend.cpp:48] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0115 21:24:50.456871 31528 slave.cpp:191] Slave started on
> 180)@172.17.0.4:52665
> I0115 21:24:50.456892 31528 slave.cpp:192] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
> --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
> --cgroups_root="mesos" --container_disk_watch_interval="15secs"
> --containerizers="mesos"
> --credential="/tmp/MasterTest_MaxCompletedFrameworksFlag_WgeCIG/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/MasterTest_MaxCompletedFrameworksFlag_WgeCIG/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --oversubscribed_resources_interval="15secs"
> --perf_duration="10secs" --perf_interval="1mins"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/MasterTest_MaxCompletedFrameworksFlag_WgeCIG"
> I0115 21:24:50.457330 31528 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_WgeCIG/credential'
> I0115 21:24:50.457607 31528 slave.cpp:322] Slave using credential for:
> test-principal
> I0115 21:24:50.457794 31528 resources.cpp:482] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0115 21:24:50.458158 31528 slave.cpp:392] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0115 21:24:50.458225 31528 slave.cpp:400] Slave attributes: [ ]
> I0115 21:24:50.458240 31528 slave.cpp:405] Slave hostname: 4e6fbf10d387
> I0115 21:24:50.458886 31507 sched.cpp:164] Version: 0.27.0
> I0115 21:24:50.459022 31529 state.cpp:58] Recovering state from
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_WgeCIG/meta'
> I0115 21:24:50.459444 31530 sched.cpp:268] New master detected at
> [email protected]:52665
> I0115 21:24:50.459512 31530 sched.cpp:324] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.459533 31530 sched.cpp:331] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.459533 31528 status_update_manager.cpp:200] Recovering status
> update manager
> I0115 21:24:50.459799 31533 containerizer.cpp:386] Recovering containerizer
> I0115 21:24:50.459832 31527 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.460209 31537 master.cpp:5521] Authenticating
> [email protected]:52665
> I0115 21:24:50.460443 31535 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(421)@172.17.0.4:52665
> I0115 21:24:50.460783 31534 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.460959 31531 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.460988 31531 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.461109 31526 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.461182 31526 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.461277 31537 provisioner.cpp:245] Provisioner recovery complete
> I0115 21:24:50.461292 31531 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.461422 31531 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.461455 31531 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.461473 31531 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.461531 31531 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.461611 31536 slave.cpp:4424] Finished recovery
> I0115 21:24:50.461697 31531 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.461837 31531 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.461853 31531 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.461886 31531 authenticator.cpp:317] Authentication success
> I0115 21:24:50.461982 31526 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.462038 31535 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> [email protected]:52665
> I0115 21:24:50.462127 31526 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(421)@172.17.0.4:52665
> I0115 21:24:50.462287 31530 sched.cpp:413] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.462297 31536 slave.cpp:4596] Querying resource estimator for
> oversubscribable resources
> I0115 21:24:50.462312 31530 sched.cpp:722] Sending SUBSCRIBE call to
> [email protected]:52665
> I0115 21:24:50.462409 31530 sched.cpp:755] Will retry registration in
> 668.85591ms if necessary
> I0115 21:24:50.462507 31536 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:52665
> I0115 21:24:50.462569 31536 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0115 21:24:50.462579 31533 status_update_manager.cpp:174] Pausing sending
> status updates
> I0115 21:24:50.462576 31530 slave.cpp:724] New master detected at
> [email protected]:52665
> I0115 21:24:50.462672 31530 slave.cpp:787] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.462698 31530 slave.cpp:792] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.462867 31530 slave.cpp:760] Detecting new master
> I0115 21:24:50.462888 31526 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.462893 31529 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0115 21:24:50.462998 31530 slave.cpp:4610] Received oversubscribable
> resources from the resource estimator
> I0115 21:24:50.463253 31526 hierarchical.cpp:259] Added framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000
> I0115 21:24:50.463321 31526 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.463361 31526 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.463366 31529 master.cpp:5521] Authenticating
> slave(180)@172.17.0.4:52665
> I0115 21:24:50.463390 31526 hierarchical.cpp:1079] Performed allocation for 0
> slaves in 113860ns
> I0115 21:24:50.463520 31535 sched.cpp:649] Framework registered with
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000
> I0115 21:24:50.463604 31535 sched.cpp:663] Scheduler::registered took 59389ns
> I0115 21:24:50.463671 31535 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(422)@172.17.0.4:52665
> I0115 21:24:50.463855 31507 sched.cpp:1851] Asked to stop the driver
> I0115 21:24:50.463966 31529 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.464064 31535 master.cpp:1211] Framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000 (default) at
> [email protected]:52665 disconnected
> I0115 21:24:50.464344 31535 master.cpp:2574] Disconnecting framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.464375 31527 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.464387 31535 master.cpp:2598] Deactivating framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.464469 31535 master.cpp:1235] Giving framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000 (default) at
> [email protected]:52665 0ns to
> failover
> I0115 21:24:50.464526 31539 hierarchical.cpp:369] Deactivated framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000
> I0115 21:24:50.464570 31527 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.464664 31536 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.464707 31536 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.464784 31536 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.464889 31536 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.464922 31536 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.464938 31536 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.464972 31536 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.465009 31536 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.465025 31536 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.465036 31536 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.465057 31536 authenticator.cpp:317] Authentication success
> I0115 21:24:50.465129 31535 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.465240 31536 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(422)@172.17.0.4:52665
> I0115 21:24:50.465210 31535 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(180)@172.17.0.4:52665
> I0115 21:24:50.465458 31529 slave.cpp:855] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.465574 31529 slave.cpp:1249] Will retry registration in
> 2.684263ms if necessary
> I0115 21:24:50.465746 31532 master.cpp:4235] Registering slave at
> slave(180)@172.17.0.4:52665 (4e6fbf10d387) with id
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0
> I0115 21:24:50.465826 31507 sched.cpp:164] Version: 0.27.0
> I0115 21:24:50.465975 31532 master.cpp:5202] Framework failover timeout,
> removing framework 2cfeb24a-de29-4273-8472-64f4f78e7791-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.466001 31532 master.cpp:5933] Removing framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.466331 31531 hierarchical.cpp:320] Removed framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0000
> I0115 21:24:50.466341 31536 registrar.cpp:439] Applied 1 operations in
> 156722ns; attempting to update the 'registry'
> I0115 21:24:50.466579 31533 sched.cpp:268] New master detected at
> [email protected]:52665
> I0115 21:24:50.466650 31533 sched.cpp:324] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.466672 31533 sched.cpp:331] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.467121 31536 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.467293 31539 log.cpp:683] Attempting to append 505 bytes to
> the log
> I0115 21:24:50.467396 31533 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 7
> I0115 21:24:50.467604 31534 master.cpp:5521] Authenticating
> [email protected]:52665
> I0115 21:24:50.467728 31541 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(423)@172.17.0.4:52665
> I0115 21:24:50.467910 31539 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.468093 31527 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.468135 31532 replica.cpp:537] Replica received write request
> for position 7 from (6134)@172.17.0.4:52665
> I0115 21:24:50.468194 31527 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.468297 31527 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.468348 31527 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.468444 31527 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.468498 31532 leveldb.cpp:341] Persisting action (524 bytes) to
> leveldb took 283472ns
> I0115 21:24:50.468531 31527 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.468638 31532 replica.cpp:712] Persisted action at 7
> I0115 21:24:50.468650 31527 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.468669 31527 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.468709 31527 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.468750 31527 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.468766 31527 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.468780 31527 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.468799 31527 authenticator.cpp:317] Authentication success
> I0115 21:24:50.469004 31526 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.469205 31526 slave.cpp:1249] Will retry registration in
> 15.360877ms if necessary
> I0115 21:24:50.469321 31528 master.cpp:4223] Ignoring register slave message
> from slave(180)@172.17.0.4:52665 (4e6fbf10d387) as admission is already in
> progress
> I0115 21:24:50.469534 31529 sched.cpp:413] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.469558 31529 sched.cpp:722] Sending SUBSCRIBE call to
> [email protected]:52665
> I0115 21:24:50.469591 31540 replica.cpp:691] Replica received learned notice
> for position 7 from @0.0.0.0:0
> I0115 21:24:50.469589 31531 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> [email protected]:52665
> I0115 21:24:50.469638 31527 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(423)@172.17.0.4:52665
> I0115 21:24:50.469655 31529 sched.cpp:755] Will retry registration in
> 1.193750527secs if necessary
> I0115 21:24:50.469772 31531 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:52665
> I0115 21:24:50.469823 31531 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0115 21:24:50.470083 31537 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0115 21:24:50.470216 31540 leveldb.cpp:341] Persisting action (526 bytes) to
> leveldb took 598843ns
> I0115 21:24:50.470243 31540 replica.cpp:712] Persisted action at 7
> I0115 21:24:50.470263 31540 replica.cpp:697] Replica learned APPEND action at
> position 7
> I0115 21:24:50.470456 31534 hierarchical.cpp:259] Added framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0001
> I0115 21:24:50.470510 31534 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.470543 31534 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.470551 31533 sched.cpp:649] Framework registered with
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0001
> I0115 21:24:50.470566 31534 hierarchical.cpp:1079] Performed allocation for 0
> slaves in 83797ns
> I0115 21:24:50.470630 31533 sched.cpp:663] Scheduler::registered took 52598ns
> I0115 21:24:50.470973 31507 sched.cpp:1851] Asked to stop the driver
> I0115 21:24:50.471055 31540 sched.cpp:1089] Stopping framework
> '2cfeb24a-de29-4273-8472-64f4f78e7791-0001'
> I0115 21:24:50.471323 31531 master.cpp:5921] Processing TEARDOWN call for
> framework 2cfeb24a-de29-4273-8472-64f4f78e7791-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.471354 31531 master.cpp:5933] Removing framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.472339 31529 hierarchical.cpp:369] Deactivated framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0001
> I0115 21:24:50.472676 31532 hierarchical.cpp:320] Removed framework
> 2cfeb24a-de29-4273-8472-64f4f78e7791-0001
> I0115 21:24:50.472966 31529 registrar.cpp:484] Successfully updated the
> 'registry' in 6.570752ms
> I0115 21:24:50.473238 31538 process.cpp:3141] Handling HTTP event for process
> 'master' with path: '/master/state'
> I0115 21:24:50.473491 31534 log.cpp:702] Attempting to truncate the log to 7
> I0115 21:24:50.473615 31539 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 8
> I0115 21:24:50.473997 31540 slave.cpp:3366] Received ping from
> slave-observer(180)@172.17.0.4:52665
> I0115 21:24:50.474072 31538 master.cpp:4303] Registered slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 at slave(180)@172.17.0.4:52665
> (4e6fbf10d387) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0115 21:24:50.474164 31540 slave.cpp:899] Registered with master
> [email protected]:52665; given slave ID
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0
> I0115 21:24:50.474184 31540 fetcher.cpp:81] Clearing fetcher cache
> I0115 21:24:50.474198 31538 http.cpp:504] HTTP GET for /master/state from
> 172.17.0.4:47473
> I0115 21:24:50.474310 31535 status_update_manager.cpp:181] Resuming sending
> status updates
> I0115 21:24:50.474421 31528 replica.cpp:537] Replica received write request
> for position 8 from (6137)@172.17.0.4:52665
> I0115 21:24:50.474534 31540 slave.cpp:922] Checkpointing SlaveInfo to
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_WgeCIG/meta/slaves/2cfeb24a-de29-4273-8472-64f4f78e7791-S0/slave.info'
> I0115 21:24:50.474570 31529 hierarchical.cpp:465] Added slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 (4e6fbf10d387) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0115 21:24:50.474717 31529 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.474745 31529 hierarchical.cpp:1101] Performed allocation for
> slave 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 in 141468ns
> I0115 21:24:50.474872 31540 slave.cpp:958] Forwarding total oversubscribed
> resources
> I0115 21:24:50.475477 31528 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 951483ns
> I0115 21:24:50.475502 31528 replica.cpp:712] Persisted action at 8
> I0115 21:24:50.475865 31538 master.cpp:4644] Received update of slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 at slave(180)@172.17.0.4:52665
> (4e6fbf10d387) with total oversubscribed resources
> I0115 21:24:50.476471 31534 replica.cpp:691] Replica received learned notice
> for position 8 from @0.0.0.0:0
> I0115 21:24:50.476759 31538 hierarchical.cpp:521] Slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 (4e6fbf10d387) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: )
> I0115 21:24:50.476892 31534 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 388146ns
> I0115 21:24:50.476959 31538 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.476963 31534 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 41808ns
> I0115 21:24:50.476990 31534 replica.cpp:712] Persisted action at 8
> I0115 21:24:50.476990 31538 hierarchical.cpp:1101] Performed allocation for
> slave 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 in 175272ns
> I0115 21:24:50.477027 31534 replica.cpp:697] Replica learned TRUNCATE action
> at position 8
> I0115 21:24:50.478739 31532 slave.cpp:596] Slave terminating
> I0115 21:24:50.478989 31539 master.cpp:1172] Slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 at slave(180)@172.17.0.4:52665
> (4e6fbf10d387) disconnected
> I0115 21:24:50.479022 31539 master.cpp:2633] Disconnecting slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 at slave(180)@172.17.0.4:52665
> (4e6fbf10d387)
> I0115 21:24:50.479084 31539 master.cpp:2652] Deactivating slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 at slave(180)@172.17.0.4:52665
> (4e6fbf10d387)
> I0115 21:24:50.479187 31532 hierarchical.cpp:550] Slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0 deactivated
> I0115 21:24:50.481765 31527 master.cpp:1025] Master terminating
> I0115 21:24:50.482199 31529 hierarchical.cpp:496] Removed slave
> 2cfeb24a-de29-4273-8472-64f4f78e7791-S0
> I0115 21:24:50.489852 31507 leveldb.cpp:174] Opened db in 2.548909ms
> I0115 21:24:50.491683 31507 leveldb.cpp:181] Compacted db in 1.800076ms
> I0115 21:24:50.491726 31507 leveldb.cpp:196] Created db iterator in 16674ns
> I0115 21:24:50.491755 31507 leveldb.cpp:202] Seeked to beginning of db in
> 13794ns
> I0115 21:24:50.491847 31507 leveldb.cpp:271] Iterated through 3 keys in the
> db in 78970ns
> I0115 21:24:50.491914 31507 replica.cpp:779] Replica recovered with log
> positions 7 -> 8 with 0 holes and 0 unlearned
> I0115 21:24:50.492436 31528 recover.cpp:447] Starting replica recovery
> I0115 21:24:50.492836 31528 recover.cpp:473] Replica is in VOTING status
> I0115 21:24:50.492997 31528 recover.cpp:462] Recover process terminated
> I0115 21:24:50.494947 31534 master.cpp:374] Master
> c692ca0d-1942-40c3-b7c7-7eede15c301a (4e6fbf10d387) started on
> 172.17.0.4:52665
> I0115 21:24:50.494973 31534 master.cpp:376] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/2wURTY/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="2"
> --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"
> --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui"
> --work_dir="/tmp/2wURTY/master" --zk_session_timeout="10secs"
> I0115 21:24:50.495375 31534 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0115 21:24:50.495391 31534 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0115 21:24:50.495463 31534 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/2wURTY/credentials'
> I0115 21:24:50.495899 31534 master.cpp:466] Using default 'crammd5'
> authenticator
> I0115 21:24:50.496062 31534 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0115 21:24:50.496302 31534 master.cpp:569] Authorization enabled
> I0115 21:24:50.496510 31537 hierarchical.cpp:147] Initialized hierarchical
> allocator process
> I0115 21:24:50.496516 31528 whitelist_watcher.cpp:77] No whitelist given
> I0115 21:24:50.498438 31534 master.cpp:1710] The newly elected leader is
> [email protected]:52665 with id c692ca0d-1942-40c3-b7c7-7eede15c301a
> I0115 21:24:50.498494 31534 master.cpp:1723] Elected as the leading master!
> I0115 21:24:50.498522 31534 master.cpp:1468] Recovering from registrar
> I0115 21:24:50.498927 31541 registrar.cpp:307] Recovering registrar
> I0115 21:24:50.499435 31531 log.cpp:659] Attempting to start the writer
> I0115 21:24:50.500466 31535 replica.cpp:493] Replica received implicit
> promise request from (6142)@172.17.0.4:52665 with proposal 3
> I0115 21:24:50.500929 31535 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 431024ns
> I0115 21:24:50.500952 31535 replica.cpp:342] Persisted promised to 3
> I0115 21:24:50.501435 31536 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0115 21:24:50.501727 31538 log.cpp:675] Writer started with ending position 8
> I0115 21:24:50.502692 31538 leveldb.cpp:436] Reading position from leveldb
> took 46663ns
> I0115 21:24:50.502779 31538 leveldb.cpp:436] Reading position from leveldb
> took 32544ns
> I0115 21:24:50.504348 31526 registrar.cpp:340] Successfully fetched the
> registry (466B) in 5.300224ms
> I0115 21:24:50.504598 31526 registrar.cpp:439] Applied 1 operations in
> 77866ns; attempting to update the 'registry'
> I0115 21:24:50.505383 31532 log.cpp:683] Attempting to append 505 bytes to
> the log
> I0115 21:24:50.505545 31527 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 9
> I0115 21:24:50.506217 31540 replica.cpp:537] Replica received write request
> for position 9 from (6143)@172.17.0.4:52665
> I0115 21:24:50.506575 31540 leveldb.cpp:341] Persisting action (524 bytes) to
> leveldb took 320628ns
> I0115 21:24:50.506600 31540 replica.cpp:712] Persisted action at 9
> I0115 21:24:50.507153 31527 replica.cpp:691] Replica received learned notice
> for position 9 from @0.0.0.0:0
> I0115 21:24:50.507509 31527 leveldb.cpp:341] Persisting action (526 bytes) to
> leveldb took 326792ns
> I0115 21:24:50.507536 31527 replica.cpp:712] Persisted action at 9
> I0115 21:24:50.507561 31527 replica.cpp:697] Replica learned APPEND action at
> position 9
> I0115 21:24:50.509042 31527 registrar.cpp:484] Successfully updated the
> 'registry' in 4.371968ms
> I0115 21:24:50.509234 31528 log.cpp:702] Attempting to truncate the log to 9
> I0115 21:24:50.509294 31527 registrar.cpp:370] Successfully recovered
> registrar
> I0115 21:24:50.509380 31539 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 10
> I0115 21:24:50.510097 31534 replica.cpp:537] Replica received write request
> for position 10 from (6144)@172.17.0.4:52665
> I0115 21:24:50.510502 31533 master.cpp:1520] Recovered 2 slaves from the
> Registry (466B) ; allowing 10mins for slaves to re-register
> I0115 21:24:50.510536 31526 hierarchical.cpp:165] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0115 21:24:50.510613 31534 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 478371ns
> I0115 21:24:50.510642 31534 replica.cpp:712] Persisted action at 10
> I0115 21:24:50.511201 31534 replica.cpp:691] Replica received learned notice
> for position 10 from @0.0.0.0:0
> I0115 21:24:50.511526 31534 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 295320ns
> I0115 21:24:50.511595 31534 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 43042ns
> I0115 21:24:50.511618 31534 replica.cpp:712] Persisted action at 10
> I0115 21:24:50.511656 31534 replica.cpp:697] Replica learned TRUNCATE action
> at position 10
> I0115 21:24:50.523950 31507 containerizer.cpp:140] Using isolation:
> posix/cpu,posix/mem,filesystem/posix
> W0115 21:24:50.524636 31507 backend.cpp:48] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0115 21:24:50.528375 31537 slave.cpp:191] Slave started on
> 181)@172.17.0.4:52665
> I0115 21:24:50.528496 31537 slave.cpp:192] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
> --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
> --cgroups_root="mesos" --container_disk_watch_interval="15secs"
> --containerizers="mesos"
> --credential="/tmp/MasterTest_MaxCompletedFrameworksFlag_TiAZce/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/MasterTest_MaxCompletedFrameworksFlag_TiAZce/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --oversubscribed_resources_interval="15secs"
> --perf_duration="10secs" --perf_interval="1mins"
> --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
> --recovery_timeout="15mins" --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/MasterTest_MaxCompletedFrameworksFlag_TiAZce"
> I0115 21:24:50.529209 31537 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_TiAZce/credential'
> I0115 21:24:50.529536 31537 slave.cpp:322] Slave using credential for:
> test-principal
> I0115 21:24:50.529855 31537 resources.cpp:482] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0115 21:24:50.530510 31537 slave.cpp:392] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0115 21:24:50.530669 31537 slave.cpp:400] Slave attributes: [ ]
> I0115 21:24:50.530782 31537 slave.cpp:405] Slave hostname: 4e6fbf10d387
> I0115 21:24:50.530922 31507 sched.cpp:164] Version: 0.27.0
> I0115 21:24:50.531680 31533 sched.cpp:268] New master detected at
> [email protected]:52665
> I0115 21:24:50.531977 31533 sched.cpp:324] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.531998 31533 sched.cpp:331] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.532127 31526 state.cpp:58] Recovering state from
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_TiAZce/meta'
> I0115 21:24:50.532227 31537 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.532560 31532 status_update_manager.cpp:200] Recovering status
> update manager
> I0115 21:24:50.532640 31526 master.cpp:5521] Authenticating
> [email protected]:52665
> I0115 21:24:50.532759 31532 containerizer.cpp:386] Recovering containerizer
> I0115 21:24:50.532979 31526 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(424)@172.17.0.4:52665
> I0115 21:24:50.533330 31526 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.533994 31528 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.534039 31528 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.534436 31539 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.534500 31539 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.534584 31539 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.534670 31539 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.534700 31539 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.534713 31539 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.534750 31539 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.534773 31539 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.534785 31539 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.534793 31539 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.534809 31539 authenticator.cpp:317] Authentication success
> I0115 21:24:50.534919 31541 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.534932 31536 provisioner.cpp:245] Provisioner recovery complete
> I0115 21:24:50.534970 31537 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> [email protected]:52665
> I0115 21:24:50.535362 31529 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(424)@172.17.0.4:52665
> I0115 21:24:50.535529 31541 sched.cpp:413] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.535554 31541 sched.cpp:722] Sending SUBSCRIBE call to
> [email protected]:52665
> I0115 21:24:50.535667 31541 sched.cpp:755] Will retry registration in
> 57.962946ms if necessary
> I0115 21:24:50.535667 31533 slave.cpp:4424] Finished recovery
> I0115 21:24:50.535864 31541 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:52665
> I0115 21:24:50.535928 31541 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0115 21:24:50.536207 31533 slave.cpp:4596] Querying resource estimator for
> oversubscribable resources
> I0115 21:24:50.536221 31541 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0115 21:24:50.536574 31533 slave.cpp:724] New master detected at
> [email protected]:52665
> I0115 21:24:50.536586 31538 status_update_manager.cpp:174] Pausing sending
> status updates
> I0115 21:24:50.536775 31533 slave.cpp:787] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.536799 31533 slave.cpp:792] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.537003 31533 slave.cpp:760] Detecting new master
> I0115 21:24:50.537127 31533 slave.cpp:4610] Received oversubscribable
> resources from the resource estimator
> I0115 21:24:50.537194 31526 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.537655 31540 hierarchical.cpp:259] Added framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0000
> I0115 21:24:50.537713 31540 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.537742 31540 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.537763 31540 hierarchical.cpp:1079] Performed allocation for 0
> slaves in 84331ns
> I0115 21:24:50.537756 31541 master.cpp:5521] Authenticating
> slave(181)@172.17.0.4:52665
> I0115 21:24:50.537900 31528 sched.cpp:649] Framework registered with
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0000
> I0115 21:24:50.538144 31528 sched.cpp:663] Scheduler::registered took 201867ns
> I0115 21:24:50.537886 31539 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(425)@172.17.0.4:52665
> I0115 21:24:50.538542 31540 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.538594 31507 sched.cpp:1851] Asked to stop the driver
> I0115 21:24:50.538723 31527 sched.cpp:1089] Stopping framework
> 'c692ca0d-1942-40c3-b7c7-7eede15c301a-0000'
> I0115 21:24:50.538761 31541 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.538787 31541 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.538934 31541 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.538995 31541 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.539106 31533 master.cpp:5921] Processing TEARDOWN call for
> framework c692ca0d-1942-40c3-b7c7-7eede15c301a-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.539189 31537 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.539284 31533 master.cpp:5933] Removing framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0000 (default) at
> [email protected]:52665
> I0115 21:24:50.539530 31537 hierarchical.cpp:369] Deactivated framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0000
> I0115 21:24:50.539551 31530 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.539580 31530 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.539592 31530 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.539621 31530 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.539644 31530 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.539655 31530 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.539664 31530 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.539680 31530 authenticator.cpp:317] Authentication success
> I0115 21:24:50.539814 31530 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.539901 31531 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(425)@172.17.0.4:52665
> I0115 21:24:50.539966 31533 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(181)@172.17.0.4:52665
> I0115 21:24:50.540165 31531 hierarchical.cpp:320] Removed framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0000
> I0115 21:24:50.540483 31530 slave.cpp:855] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.540606 31530 slave.cpp:1249] Will retry registration in
> 160421ns if necessary
> I0115 21:24:50.540819 31538 master.cpp:4235] Registering slave at
> slave(181)@172.17.0.4:52665 (4e6fbf10d387) with id
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0
> I0115 21:24:50.541365 31535 registrar.cpp:439] Applied 1 operations in
> 92849ns; attempting to update the 'registry'
> I0115 21:24:50.542291 31535 slave.cpp:1249] Will retry registration in
> 9.446155ms if necessary
> I0115 21:24:50.542424 31535 log.cpp:683] Attempting to append 671 bytes to
> the log
> I0115 21:24:50.542562 31527 master.cpp:4223] Ignoring register slave message
> from slave(181)@172.17.0.4:52665 (4e6fbf10d387) as admission is already in
> progress
> I0115 21:24:50.542613 31535 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 11
> I0115 21:24:50.543368 31540 replica.cpp:537] Replica received write request
> for position 11 from (6158)@172.17.0.4:52665
> I0115 21:24:50.543472 31507 sched.cpp:164] Version: 0.27.0
> I0115 21:24:50.543937 31540 leveldb.cpp:341] Persisting action (690 bytes) to
> leveldb took 443903ns
> I0115 21:24:50.543974 31540 replica.cpp:712] Persisted action at 11
> I0115 21:24:50.544502 31532 sched.cpp:268] New master detected at
> [email protected]:52665
> I0115 21:24:50.544642 31532 sched.cpp:324] Authenticating with master
> [email protected]:52665
> I0115 21:24:50.544663 31532 sched.cpp:331] Using default CRAM-MD5
> authenticatee
> I0115 21:24:50.544906 31531 replica.cpp:691] Replica received learned notice
> for position 11 from @0.0.0.0:0
> I0115 21:24:50.545123 31530 authenticatee.cpp:121] Creating new client SASL
> connection
> I0115 21:24:50.545377 31531 leveldb.cpp:341] Persisting action (692 bytes) to
> leveldb took 439333ns
> I0115 21:24:50.545418 31531 replica.cpp:712] Persisted action at 11
> I0115 21:24:50.545445 31531 replica.cpp:697] Replica learned APPEND action at
> position 11
> I0115 21:24:50.545593 31535 master.cpp:5521] Authenticating
> [email protected]:52665
> I0115 21:24:50.545809 31529 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(426)@172.17.0.4:52665
> I0115 21:24:50.546036 31532 authenticator.cpp:98] Creating new server SASL
> connection
> I0115 21:24:50.546748 31532 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0115 21:24:50.546958 31532 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0115 21:24:50.547176 31532 authenticator.cpp:203] Received SASL
> authentication start
> I0115 21:24:50.547238 31532 authenticator.cpp:325] Authentication requires
> more steps
> I0115 21:24:50.547322 31532 authenticatee.cpp:258] Received SASL
> authentication step
> I0115 21:24:50.547577 31532 authenticator.cpp:231] Received SASL
> authentication step
> I0115 21:24:50.547608 31532 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0115 21:24:50.547624 31532 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0115 21:24:50.547668 31532 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0115 21:24:50.547693 31532 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: '4e6fbf10d387' server FQDN: '4e6fbf10d387'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0115 21:24:50.547704 31532 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.547713 31532 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0115 21:24:50.547729 31532 authenticator.cpp:317] Authentication success
> I0115 21:24:50.547865 31529 authenticatee.cpp:298] Authentication success
> I0115 21:24:50.548017 31529 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> [email protected]:52665
> I0115 21:24:50.548152 31529 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(426)@172.17.0.4:52665
> I0115 21:24:50.548521 31532 sched.cpp:413] Successfully authenticated with
> master [email protected]:52665
> I0115 21:24:50.548734 31532 sched.cpp:722] Sending SUBSCRIBE call to
> [email protected]:52665
> I0115 21:24:50.548815 31526 registrar.cpp:484] Successfully updated the
> 'registry' in 7.357696ms
> I0115 21:24:50.549026 31532 sched.cpp:755] Will retry registration in
> 510.878524ms if necessary
> I0115 21:24:50.549149 31528 log.cpp:702] Attempting to truncate the log to 11
> I0115 21:24:50.549211 31530 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:52665
> I0115 21:24:50.549324 31530 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0115 21:24:50.549394 31532 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 12
> I0115 21:24:50.549675 31530 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0115 21:24:50.550137 31531 hierarchical.cpp:259] Added framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001
> I0115 21:24:50.550261 31531 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.550411 31532 sched.cpp:649] Framework registered with
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001
> I0115 21:24:50.550660 31532 sched.cpp:663] Scheduler::registered took 52837ns
> I0115 21:24:50.550513 31527 replica.cpp:537] Replica received write request
> for position 12 from (6159)@172.17.0.4:52665
> I0115 21:24:50.550734 31530 master.cpp:4303] Registered slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 at slave(181)@172.17.0.4:52665
> (4e6fbf10d387) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0115 21:24:50.550837 31532 slave.cpp:3366] Received ping from
> slave-observer(181)@172.17.0.4:52665
> I0115 21:24:50.550947 31531 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.550971 31532 slave.cpp:899] Registered with master
> [email protected]:52665; given slave ID
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0
> I0115 21:24:50.551100 31531 hierarchical.cpp:1079] Performed allocation for 0
> slaves in 864753ns
> I0115 21:24:50.551113 31532 fetcher.cpp:81] Clearing fetcher cache
> I0115 21:24:50.551214 31527 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 411593ns
> I0115 21:24:50.551260 31527 replica.cpp:712] Persisted action at 12
> I0115 21:24:50.551365 31527 status_update_manager.cpp:181] Resuming sending
> status updates
> I0115 21:24:50.551446 31532 slave.cpp:922] Checkpointing SlaveInfo to
> '/tmp/MasterTest_MaxCompletedFrameworksFlag_TiAZce/meta/slaves/c692ca0d-1942-40c3-b7c7-7eede15c301a-S0/slave.info'
> I0115 21:24:50.551671 31531 hierarchical.cpp:465] Added slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 (4e6fbf10d387) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0115 21:24:50.551877 31532 slave.cpp:958] Forwarding total oversubscribed
> resources
> I0115 21:24:50.552701 31507 sched.cpp:1851] Asked to stop the driver
> I0115 21:24:50.552909 31526 master.cpp:4644] Received update of slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 at slave(181)@172.17.0.4:52665
> (4e6fbf10d387) with total oversubscribed resources
> I0115 21:24:50.553128 31536 replica.cpp:691] Replica received learned notice
> for position 12 from @0.0.0.0:0
> I0115 21:24:50.553720 31531 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.553853 31531 hierarchical.cpp:1101] Performed allocation for
> slave c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 in 2.136878ms
> I0115 21:24:50.554111 31536 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 871515ns
> I0115 21:24:50.554184 31536 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 43002ns
> I0115 21:24:50.554211 31536 replica.cpp:712] Persisted action at 12
> I0115 21:24:50.554234 31536 replica.cpp:697] Replica learned TRUNCATE action
> at position 12
> I0115 21:24:50.554656 31531 hierarchical.cpp:521] Slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 (4e6fbf10d387) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0115 21:24:50.554931 31531 hierarchical.cpp:1329] No resources available to
> allocate!
> I0115 21:24:50.555027 31531 hierarchical.cpp:1423] No inverse offers to send
> out!
> I0115 21:24:50.555120 31531 hierarchical.cpp:1101] Performed allocation for
> slave c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 in 348381ns
> I0115 21:24:50.553755 31526 master.cpp:1211] Framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 (default) at
> [email protected]:52665 disconnected
> I0115 21:24:50.555299 31526 master.cpp:2574] Disconnecting framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.555424 31526 master.cpp:2598] Deactivating framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.555618 31526 master.cpp:1235] Giving framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 (default) at
> [email protected]:52665 0ns to
> failover
> I0115 21:24:50.555713 31540 hierarchical.cpp:369] Deactivated framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001
> W0115 21:24:50.556005 31526 master.cpp:5215] Master returning resources
> offered to framework c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 because the
> framework has terminated or is inactive
> I0115 21:24:50.556226 31526 process.cpp:3141] Handling HTTP event for process
> 'master' with path: '/master/state'
> I0115 21:24:50.556789 31537 hierarchical.cpp:880] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 from framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001
> I0115 21:24:50.556864 31533 http.cpp:504] HTTP GET for /master/state from
> 172.17.0.4:47474
> I0115 21:24:50.558725 31533 master.cpp:5202] Framework failover timeout,
> removing framework c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.558771 31533 master.cpp:5933] Removing framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 (default) at
> [email protected]:52665
> I0115 21:24:50.558904 31538 slave.cpp:2007] Asked to shut down framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001 by [email protected]:52665
> W0115 21:24:50.558939 31538 slave.cpp:2022] Cannot shut down unknown
> framework c692ca0d-1942-40c3-b7c7-7eede15c301a-0001
> I0115 21:24:50.559340 31538 hierarchical.cpp:320] Removed framework
> c692ca0d-1942-40c3-b7c7-7eede15c301a-0001
> ../../src/tests/master_tests.cpp:3976: Failure
> Value of: completedFrameworks->values.size()
> Actual: 1
> Expected: maxFrameworks
> Which is: 2
> I0115 21:24:50.562002 31531 slave.cpp:596] Slave terminating
> I0115 21:24:50.562175 31539 master.cpp:1172] Slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 at slave(181)@172.17.0.4:52665
> (4e6fbf10d387) disconnected
> I0115 21:24:50.562209 31539 master.cpp:2633] Disconnecting slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 at slave(181)@172.17.0.4:52665
> (4e6fbf10d387)
> I0115 21:24:50.562284 31539 master.cpp:2652] Deactivating slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 at slave(181)@172.17.0.4:52665
> (4e6fbf10d387)
> I0115 21:24:50.562458 31533 hierarchical.cpp:550] Slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0 deactivated
> I0115 21:24:50.565102 31526 master.cpp:1025] Master terminating
> I0115 21:24:50.565763 31529 hierarchical.cpp:496] Removed slave
> c692ca0d-1942-40c3-b7c7-7eede15c301a-S0
> [ FAILED ] MasterTest.MaxCompletedFrameworksFlag (231 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
