[
https://issues.apache.org/jira/browse/MESOS-4518?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Benjamin Mahler updated MESOS-4518:
-----------------------------------
Shepherd: Benjamin Mahler
> MasterTest.MaxCompletedTasksPerFrameworkFlag is flaky
> -----------------------------------------------------
>
> Key: MESOS-4518
> URL: https://issues.apache.org/jira/browse/MESOS-4518
> Project: Mesos
> Issue Type: Bug
> Components: tests
> Affects Versions: 0.26.0
> Environment: CentOS 7 with gcc
> Reporter: Greg Mann
> Assignee: Kevin Klues
> Labels: flaky-test, master, mesosphere
>
> Just observed this on ASF CI, CentOS 7 with gcc:
> {code}
> [ RUN ] MasterTest.MaxCompletedTasksPerFrameworkFlag
> I0126 21:09:41.845321 800 leveldb.cpp:174] Opened db in 2.419582ms
> I0126 21:09:41.846269 800 leveldb.cpp:181] Compacted db in 782855ns
> I0126 21:09:41.846392 800 leveldb.cpp:196] Created db iterator in 22135ns
> I0126 21:09:41.846416 800 leveldb.cpp:202] Seeked to beginning of db in
> 1956ns
> I0126 21:09:41.846431 800 leveldb.cpp:271] Iterated through 0 keys in the
> db in 388ns
> I0126 21:09:41.846479 800 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0126 21:09:41.846972 824 recover.cpp:447] Starting replica recovery
> I0126 21:09:41.847550 824 recover.cpp:473] Replica is in EMPTY status
> I0126 21:09:41.849726 822 master.cpp:374] Master
> aed72a2b-829f-4ec9-b33a-5fac9421d44f (c0bf249b6465) started on
> 172.17.0.5:52680
> I0126 21:09:41.849967 822 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/a6rJ4B/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="0" --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/a6rJ4B/master" --zk_session_timeout="10secs"
> I0126 21:09:41.850344 822 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0126 21:09:41.850358 822 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0126 21:09:41.850368 822 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/a6rJ4B/credentials'
> I0126 21:09:41.851260 822 master.cpp:466] Using default 'crammd5'
> authenticator
> I0126 21:09:41.851419 822 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0126 21:09:41.851541 822 master.cpp:569] Authorization enabled
> I0126 21:09:41.853004 832 whitelist_watcher.cpp:77] No whitelist given
> I0126 21:09:41.853294 820 hierarchical.cpp:144] Initialized hierarchical
> allocator process
> I0126 21:09:41.853672 822 master.cpp:1710] The newly elected leader is
> master@172.17.0.5:52680 with id aed72a2b-829f-4ec9-b33a-5fac9421d44f
> I0126 21:09:41.853703 822 master.cpp:1723] Elected as the leading master!
> I0126 21:09:41.853724 822 master.cpp:1468] Recovering from registrar
> I0126 21:09:41.853865 824 registrar.cpp:307] Recovering registrar
> I0126 21:09:41.854243 826 replica.cpp:673] Replica in EMPTY status received
> a broadcasted recover request from (6072)@172.17.0.5:52680
> I0126 21:09:41.854653 823 recover.cpp:193] Received a recover response from
> a replica in EMPTY status
> I0126 21:09:41.855304 829 recover.cpp:564] Updating replica status to
> STARTING
> I0126 21:09:41.856170 828 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 727738ns
> I0126 21:09:41.856199 828 replica.cpp:320] Persisted replica status to
> STARTING
> I0126 21:09:41.856493 828 recover.cpp:473] Replica is in STARTING status
> I0126 21:09:41.857712 834 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (6073)@172.17.0.5:52680
> I0126 21:09:41.858253 830 recover.cpp:193] Received a recover response from
> a replica in STARTING status
> I0126 21:09:41.858752 830 recover.cpp:564] Updating replica status to VOTING
> I0126 21:09:41.860528 824 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 1.492538ms
> I0126 21:09:41.860620 824 replica.cpp:320] Persisted replica status to
> VOTING
> I0126 21:09:41.860924 824 recover.cpp:578] Successfully joined the Paxos
> group
> I0126 21:09:41.861613 824 recover.cpp:462] Recover process terminated
> I0126 21:09:41.862511 824 log.cpp:659] Attempting to start the writer
> I0126 21:09:41.863821 826 replica.cpp:493] Replica received implicit
> promise request from (6074)@172.17.0.5:52680 with proposal 1
> I0126 21:09:41.864397 826 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 535372ns
> I0126 21:09:41.864421 826 replica.cpp:342] Persisted promised to 1
> I0126 21:09:41.865295 826 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0126 21:09:41.866762 819 replica.cpp:388] Replica received explicit
> promise request from (6075)@172.17.0.5:52680 for position 0 with proposal 2
> I0126 21:09:41.867246 819 leveldb.cpp:341] Persisting action (8 bytes) to
> leveldb took 439679ns
> I0126 21:09:41.867272 819 replica.cpp:712] Persisted action at 0
> I0126 21:09:41.868392 828 replica.cpp:537] Replica received write request
> for position 0 from (6076)@172.17.0.5:52680
> I0126 21:09:41.868459 828 leveldb.cpp:436] Reading position from leveldb
> took 33892ns
> I0126 21:09:41.869012 828 leveldb.cpp:341] Persisting action (14 bytes) to
> leveldb took 497113ns
> I0126 21:09:41.869040 828 replica.cpp:712] Persisted action at 0
> I0126 21:09:41.869662 834 replica.cpp:691] Replica received learned notice
> for position 0 from @0.0.0.0:0
> I0126 21:09:41.870192 834 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 497497ns
> I0126 21:09:41.870219 834 replica.cpp:712] Persisted action at 0
> I0126 21:09:41.870242 834 replica.cpp:697] Replica learned NOP action at
> position 0
> I0126 21:09:41.870903 834 log.cpp:675] Writer started with ending position 0
> I0126 21:09:41.872077 820 leveldb.cpp:436] Reading position from leveldb
> took 28742ns
> I0126 21:09:41.873145 824 registrar.cpp:340] Successfully fetched the
> registry (0B) in 19.234048ms
> I0126 21:09:41.873353 824 registrar.cpp:439] Applied 1 operations in
> 29163ns; attempting to update the 'registry'
> I0126 21:09:41.874145 824 log.cpp:683] Attempting to append 170 bytes to
> the log
> I0126 21:09:41.874302 820 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0126 21:09:41.875190 819 replica.cpp:537] Replica received write request
> for position 1 from (6077)@172.17.0.5:52680
> I0126 21:09:41.875649 819 leveldb.cpp:341] Persisting action (189 bytes) to
> leveldb took 410747ns
> I0126 21:09:41.875675 819 replica.cpp:712] Persisted action at 1
> I0126 21:09:41.876298 819 replica.cpp:691] Replica received learned notice
> for position 1 from @0.0.0.0:0
> I0126 21:09:41.876754 819 leveldb.cpp:341] Persisting action (191 bytes) to
> leveldb took 348593ns
> I0126 21:09:41.876790 819 replica.cpp:712] Persisted action at 1
> I0126 21:09:41.876816 819 replica.cpp:697] Replica learned APPEND action at
> position 1
> I0126 21:09:41.877727 820 registrar.cpp:484] Successfully updated the
> 'registry' in 4.29184ms
> I0126 21:09:41.877915 820 registrar.cpp:370] Successfully recovered
> registrar
> I0126 21:09:41.878182 825 log.cpp:702] Attempting to truncate the log to 1
> I0126 21:09:41.878329 822 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0126 21:09:41.878669 823 master.cpp:1520] Recovered 0 slaves from the
> Registry (131B) ; allowing 10mins for slaves to re-register
> I0126 21:09:41.878862 822 hierarchical.cpp:171] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0126 21:09:41.879472 819 replica.cpp:537] Replica received write request
> for position 2 from (6078)@172.17.0.5:52680
> I0126 21:09:41.880218 819 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 711112ns
> I0126 21:09:41.880251 819 replica.cpp:712] Persisted action at 2
> I0126 21:09:41.881042 819 replica.cpp:691] Replica received learned notice
> for position 2 from @0.0.0.0:0
> I0126 21:09:41.883219 819 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 2.081559ms
> I0126 21:09:41.883293 819 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 38100ns
> I0126 21:09:41.883319 819 replica.cpp:712] Persisted action at 2
> I0126 21:09:41.883345 819 replica.cpp:697] Replica learned TRUNCATE action
> at position 2
> I0126 21:09:41.894690 830 slave.cpp:192] Slave started on
> 177)@172.17.0.5:52680
> I0126 21:09:41.895045 830 slave.cpp:193] 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_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/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_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/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_MaxCompletedTasksPerFrameworkFlag_sZhbcJ"
> I0126 21:09:41.895640 830 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/credential'
> I0126 21:09:41.895894 830 slave.cpp:323] Slave using credential for:
> test-principal
> I0126 21:09:41.896149 830 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0126 21:09:41.896744 830 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0126 21:09:41.896888 830 slave.cpp:471] Slave attributes: [ ]
> I0126 21:09:41.896991 830 slave.cpp:476] Slave hostname: c0bf249b6465
> I0126 21:09:41.897442 800 sched.cpp:222] Version: 0.27.0
> I0126 21:09:41.898279 830 state.cpp:58] Recovering state from
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/meta'
> I0126 21:09:41.898733 829 sched.cpp:326] New master detected at
> master@172.17.0.5:52680
> I0126 21:09:41.898799 834 status_update_manager.cpp:200] Recovering status
> update manager
> I0126 21:09:41.899024 829 sched.cpp:382] Authenticating with master
> master@172.17.0.5:52680
> I0126 21:09:41.899124 834 slave.cpp:4495] Finished recovery
> I0126 21:09:41.899130 829 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0126 21:09:41.899646 834 slave.cpp:4667] Querying resource estimator for
> oversubscribable resources
> I0126 21:09:41.900012 829 authenticatee.cpp:121] Creating new client SASL
> connection
> I0126 21:09:41.900171 834 status_update_manager.cpp:174] Pausing sending
> status updates
> I0126 21:09:41.900041 825 slave.cpp:795] New master detected at
> master@172.17.0.5:52680
> I0126 21:09:41.900249 825 slave.cpp:858] Authenticating with master
> master@172.17.0.5:52680
> I0126 21:09:41.900269 825 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0126 21:09:41.900399 825 slave.cpp:831] Detecting new master
> I0126 21:09:41.900516 825 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0126 21:09:41.900658 825 authenticatee.cpp:121] Creating new client SASL
> connection
> I0126 21:09:41.900899 829 master.cpp:5521] Authenticating
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:41.901700 822 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(423)@172.17.0.5:52680
> I0126 21:09:41.901813 829 master.cpp:5521] Authenticating
> slave(177)@172.17.0.5:52680
> I0126 21:09:41.902150 834 authenticator.cpp:98] Creating new server SASL
> connection
> I0126 21:09:41.902293 822 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(424)@172.17.0.5:52680
> I0126 21:09:41.902374 834 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0126 21:09:41.902436 834 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0126 21:09:41.902523 834 authenticator.cpp:203] Received SASL
> authentication start
> I0126 21:09:41.902590 834 authenticator.cpp:325] Authentication requires
> more steps
> I0126 21:09:41.902670 834 authenticatee.cpp:258] Received SASL
> authentication step
> I0126 21:09:41.902863 827 authenticator.cpp:98] Creating new server SASL
> connection
> I0126 21:09:41.903120 827 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0126 21:09:41.903149 827 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0126 21:09:41.903224 827 authenticator.cpp:203] Received SASL
> authentication start
> I0126 21:09:41.903270 827 authenticator.cpp:325] Authentication requires
> more steps
> I0126 21:09:41.903342 827 authenticatee.cpp:258] Received SASL
> authentication step
> I0126 21:09:41.903430 827 authenticator.cpp:231] Received SASL
> authentication step
> I0126 21:09:41.903462 827 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0126 21:09:41.903476 827 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0126 21:09:41.903522 827 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0126 21:09:41.903547 827 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0126 21:09:41.903559 827 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:41.903568 827 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:41.903586 827 authenticator.cpp:317] Authentication success
> I0126 21:09:41.903744 827 authenticatee.cpp:298] Authentication success
> I0126 21:09:41.903833 827 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(177)@172.17.0.5:52680
> I0126 21:09:41.903923 827 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(424)@172.17.0.5:52680
> I0126 21:09:41.904167 833 slave.cpp:926] Successfully authenticated with
> master master@172.17.0.5:52680
> I0126 21:09:41.904302 833 slave.cpp:1320] Will retry registration in
> 752697ns if necessary
> I0126 21:09:41.904630 833 master.cpp:4235] Registering slave at
> slave(177)@172.17.0.5:52680 (c0bf249b6465) with id
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0
> I0126 21:09:41.905086 823 authenticator.cpp:231] Received SASL
> authentication step
> I0126 21:09:41.905120 823 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0126 21:09:41.905134 823 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0126 21:09:41.905169 823 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0126 21:09:41.905195 823 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0126 21:09:41.905208 823 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:41.905210 833 registrar.cpp:439] Applied 1 operations in
> 74169ns; attempting to update the 'registry'
> I0126 21:09:41.905217 823 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:41.905253 823 authenticator.cpp:317] Authentication success
> I0126 21:09:41.905419 823 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:41.905413 828 authenticatee.cpp:298] Authentication success
> I0126 21:09:41.906111 827 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(423)@172.17.0.5:52680
> I0126 21:09:41.906407 829 slave.cpp:1320] Will retry registration in
> 38.620672ms if necessary
> I0126 21:09:41.906512 828 sched.cpp:471] Successfully authenticated with
> master master@172.17.0.5:52680
> I0126 21:09:41.906522 827 master.cpp:4223] Ignoring register slave message
> from slave(177)@172.17.0.5:52680 (c0bf249b6465) as admission is already in
> progress
> I0126 21:09:41.906533 828 sched.cpp:780] Sending SUBSCRIBE call to
> master@172.17.0.5:52680
> I0126 21:09:41.906644 828 sched.cpp:813] Will retry registration in
> 1.219935675secs if necessary
> I0126 21:09:41.906798 828 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:41.906859 828 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0126 21:09:41.907558 828 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0126 21:09:41.907929 823 log.cpp:683] Attempting to append 339 bytes to
> the log
> I0126 21:09:41.908315 823 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 3
> I0126 21:09:41.909303 829 hierarchical.cpp:265] Added framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.910217 821 sched.cpp:707] Framework registered with
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.910321 821 sched.cpp:721] Scheduler::registered took 64827ns
> I0126 21:09:41.910221 829 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:41.910679 829 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:41.910712 829 hierarchical.cpp:1090] Performed allocation for 0
> slaves in 658337ns
> I0126 21:09:41.909553 823 replica.cpp:537] Replica received write request
> for position 3 from (6083)@172.17.0.5:52680
> I0126 21:09:41.911563 823 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 763795ns
> I0126 21:09:41.911594 823 replica.cpp:712] Persisted action at 3
> I0126 21:09:41.912735 823 replica.cpp:691] Replica received learned notice
> for position 3 from @0.0.0.0:0
> I0126 21:09:41.913324 823 leveldb.cpp:341] Persisting action (360 bytes) to
> leveldb took 553053ns
> I0126 21:09:41.913429 823 replica.cpp:712] Persisted action at 3
> I0126 21:09:41.913548 823 replica.cpp:697] Replica learned APPEND action at
> position 3
> I0126 21:09:41.915766 826 registrar.cpp:484] Successfully updated the
> 'registry' in 10.465024ms
> I0126 21:09:41.916115 823 log.cpp:702] Attempting to truncate the log to 3
> I0126 21:09:41.916374 823 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 4
> I0126 21:09:41.916997 826 master.cpp:4303] Registered slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0126 21:09:41.917083 822 slave.cpp:970] Registered with master
> master@172.17.0.5:52680; given slave ID
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0
> I0126 21:09:41.917516 822 fetcher.cpp:81] Clearing fetcher cache
> I0126 21:09:41.917544 833 replica.cpp:537] Replica received write request
> for position 4 from (6084)@172.17.0.5:52680
> I0126 21:09:41.917306 824 hierarchical.cpp:471] Added slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 (c0bf249b6465) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0126 21:09:41.918018 826 status_update_manager.cpp:181] Resuming sending
> status updates
> I0126 21:09:41.918193 833 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 526388ns
> I0126 21:09:41.918223 833 replica.cpp:712] Persisted action at 4
> I0126 21:09:41.918793 824 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:41.918838 824 hierarchical.cpp:1110] Performed allocation for
> slave aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 in 1.172464ms
> I0126 21:09:41.919239 822 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/meta/slaves/aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0/slave.info'
> I0126 21:09:41.919900 824 master.cpp:5350] Sending 1 offers to framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:41.920068 822 slave.cpp:1029] Forwarding total oversubscribed
> resources
> I0126 21:09:41.920295 824 master.cpp:4644] Received update of slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465) with total oversubscribed resources
> I0126 21:09:41.920722 826 sched.cpp:877] Scheduler::resourceOffers took
> 142253ns
> I0126 21:09:41.920332 832 replica.cpp:691] Replica received learned notice
> for position 4 from @0.0.0.0:0
> I0126 21:09:41.921336 824 hierarchical.cpp:527] Slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 (c0bf249b6465) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0126 21:09:41.921684 824 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:41.921792 824 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:41.921900 824 hierarchical.cpp:1110] Performed allocation for
> slave aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 in 387614ns
> I0126 21:09:41.922184 823 slave.cpp:3435] Received ping from
> slave-observer(181)@172.17.0.5:52680
> I0126 21:09:41.921452 832 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 578762ns
> I0126 21:09:41.922531 832 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 50682ns
> I0126 21:09:41.922685 832 replica.cpp:712] Persisted action at 4
> I0126 21:09:41.922847 832 replica.cpp:697] Replica learned TRUNCATE action
> at position 4
> I0126 21:09:41.923763 824 master.cpp:3136] Processing ACCEPT call for
> offers: [ aed72a2b-829f-4ec9-b33a-5fac9421d44f-O0 ] on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465) for framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> (default) at scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:41.924221 824 master.cpp:2823] Authorizing framework principal
> 'test-principal' to launch task 0 as user 'mesos'
> W0126 21:09:41.926131 824 validation.cpp:404] Executor default for task 0
> uses less CPUs (None) than the minimum required (0.01). Please update your
> executor, as this will be mandatory in future releases.
> W0126 21:09:41.926306 824 validation.cpp:416] Executor default for task 0
> uses less memory (None) than the minimum required (32MB). Please update your
> executor, as this will be mandatory in future releases.
> I0126 21:09:41.926859 824 master.hpp:176] Adding task 0 with resources
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 (c0bf249b6465)
> I0126 21:09:41.927238 824 master.cpp:3621] Launching task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:41.927824 825 slave.cpp:1360] Got assigned task 0 for framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.928578 825 slave.cpp:1479] Launching task 0 for framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.929510 825 paths.cpp:472] Trying to chown
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/slaves/aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0/frameworks/aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000/executors/default/runs/4dc824fb-0da7-4811-b9ea-84e2d4fc6c0b'
> to user 'mesos'
> I0126 21:09:41.940620 825 slave.cpp:5281] Launching executor default of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 with resources in work
> directory
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/slaves/aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0/frameworks/aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000/executors/default/runs/4dc824fb-0da7-4811-b9ea-84e2d4fc6c0b'
> I0126 21:09:41.942904 825 exec.cpp:134] Version: 0.27.0
> I0126 21:09:41.943213 826 exec.cpp:184] Executor started at:
> executor(74)@172.17.0.5:52680 with pid 800
> I0126 21:09:41.943536 825 slave.cpp:1697] Queuing task '0' for executor
> 'default' of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.943768 825 slave.cpp:748] Successfully attached file
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_sZhbcJ/slaves/aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0/frameworks/aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000/executors/default/runs/4dc824fb-0da7-4811-b9ea-84e2d4fc6c0b'
> I0126 21:09:41.944105 825 slave.cpp:2642] Got registration for executor
> 'default' of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 from
> executor(74)@172.17.0.5:52680
> I0126 21:09:41.945487 826 exec.cpp:208] Executor registered on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0
> I0126 21:09:41.945924 826 exec.cpp:220] Executor::registered took 30525ns
> I0126 21:09:41.946091 825 slave.cpp:1862] Sending queued task '0' to
> executor 'default' of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 at
> executor(74)@172.17.0.5:52680
> I0126 21:09:41.946663 832 exec.cpp:295] Executor asked to run task '0'
> I0126 21:09:41.946758 832 exec.cpp:304] Executor::launchTask took 70200ns
> I0126 21:09:41.946871 832 exec.cpp:517] Executor sending status update
> TASK_FINISHED (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.947279 825 slave.cpp:3001] Handling status update
> TASK_FINISHED (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 from
> executor(74)@172.17.0.5:52680
> I0126 21:09:41.947419 825 slave.cpp:5591] Terminating task 0
> I0126 21:09:41.948118 828 status_update_manager.cpp:320] Received status
> update TASK_FINISHED (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0
> of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.948168 828 status_update_manager.cpp:497] Creating
> StatusUpdate stream for task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.948566 828 status_update_manager.cpp:374] Forwarding update
> TASK_FINISHED (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 to the slave
> I0126 21:09:41.948848 821 slave.cpp:3353] Forwarding the update
> TASK_FINISHED (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 to master@172.17.0.5:52680
> I0126 21:09:41.949214 821 slave.cpp:3247] Status update manager
> successfully handled status update TASK_FINISHED (UUID:
> 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.949375 821 slave.cpp:3263] Sending acknowledgement for
> status update TASK_FINISHED (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for
> task 0 of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 to
> executor(74)@172.17.0.5:52680
> I0126 21:09:41.949456 828 master.cpp:4789] Status update TASK_FINISHED
> (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 from slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:41.949602 828 master.cpp:4837] Forwarding status update
> TASK_FINISHED (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.949813 830 exec.cpp:341] Executor received status update
> acknowledgement 28f64b46-7703-4ea1-859c-1a2516aad83d for task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.950083 828 master.cpp:6445] Updating the state of task 0 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (latest state:
> TASK_FINISHED, status update state: TASK_FINISHED)
> I0126 21:09:41.950232 830 sched.cpp:985] Scheduler::statusUpdate took
> 121682ns
> I0126 21:09:41.950892 831 hierarchical.cpp:886] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 from framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.951566 830 master.cpp:3947] Processing ACKNOWLEDGE call
> 28f64b46-7703-4ea1-859c-1a2516aad83d for task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680 on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0
> I0126 21:09:41.951630 830 master.cpp:6511] Removing task 0 with resources
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:41.952141 822 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: 28f64b46-7703-4ea1-859c-1a2516aad83d) for task
> 0 of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.952311 822 status_update_manager.cpp:528] Cleaning up status
> update stream for task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.952625 823 slave.cpp:2411] Status update manager
> successfully handled status update acknowledgement (UUID:
> 28f64b46-7703-4ea1-859c-1a2516aad83d) for task 0 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:41.952675 823 slave.cpp:5632] Completing task 0
> 2016-01-26
> 21:09:42,463:800(0x7f7b957b6700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36129] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0126 21:09:42.855146 830 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:42.856165 821 master.cpp:5350] Sending 1 offers to framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:42.856415 830 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 2.507956ms
> I0126 21:09:42.857444 821 sched.cpp:877] Scheduler::resourceOffers took
> 148050ns
> I0126 21:09:42.859411 821 master.cpp:3136] Processing ACCEPT call for
> offers: [ aed72a2b-829f-4ec9-b33a-5fac9421d44f-O1 ] on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465) for framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> (default) at scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:42.859769 821 master.cpp:2823] Authorizing framework principal
> 'test-principal' to launch task 1 as user 'mesos'
> W0126 21:09:42.861827 821 validation.cpp:404] Executor default for task 1
> uses less CPUs (None) than the minimum required (0.01). Please update your
> executor, as this will be mandatory in future releases.
> W0126 21:09:42.862216 821 validation.cpp:416] Executor default for task 1
> uses less memory (None) than the minimum required (32MB). Please update your
> executor, as this will be mandatory in future releases.
> I0126 21:09:42.863005 821 master.hpp:176] Adding task 1 with resources
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 (c0bf249b6465)
> I0126 21:09:42.863629 821 master.cpp:3621] Launching task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> slave aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:42.864377 830 slave.cpp:1360] Got assigned task 1 for framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.864833 830 slave.cpp:1479] Launching task 1 for framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.864975 830 slave.cpp:1710] Queuing task '1' for executor
> 'default' of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 at
> executor(74)@172.17.0.5:52680
> I0126 21:09:42.865722 830 slave.cpp:1862] Sending queued task '1' to
> executor 'default' of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 at
> executor(74)@172.17.0.5:52680
> I0126 21:09:42.866132 821 exec.cpp:295] Executor asked to run task '1'
> I0126 21:09:42.866591 821 exec.cpp:304] Executor::launchTask took 139245ns
> I0126 21:09:42.867055 821 exec.cpp:517] Executor sending status update
> TASK_FINISHED (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.867697 830 slave.cpp:3001] Handling status update
> TASK_FINISHED (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 from
> executor(74)@172.17.0.5:52680
> I0126 21:09:42.867830 830 slave.cpp:5591] Terminating task 1
> I0126 21:09:42.868569 823 status_update_manager.cpp:320] Received status
> update TASK_FINISHED (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1
> of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.868964 823 status_update_manager.cpp:497] Creating
> StatusUpdate stream for task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.869779 823 status_update_manager.cpp:374] Forwarding update
> TASK_FINISHED (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 to the slave
> I0126 21:09:42.870641 823 slave.cpp:3353] Forwarding the update
> TASK_FINISHED (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 to master@172.17.0.5:52680
> I0126 21:09:42.871245 823 slave.cpp:3247] Status update manager
> successfully handled status update TASK_FINISHED (UUID:
> 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.871620 823 slave.cpp:3263] Sending acknowledgement for
> status update TASK_FINISHED (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for
> task 1 of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 to
> executor(74)@172.17.0.5:52680
> I0126 21:09:42.872277 823 master.cpp:4789] Status update TASK_FINISHED
> (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 from slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:42.872618 823 master.cpp:4837] Forwarding status update
> TASK_FINISHED (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.873194 823 master.cpp:6445] Updating the state of task 1 of
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (latest state:
> TASK_FINISHED, status update state: TASK_FINISHED)
> I0126 21:09:42.874096 823 exec.cpp:341] Executor received status update
> acknowledgement 60cc98f4-e6bb-4605-800a-fff974b814da for task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.874779 823 sched.cpp:985] Scheduler::statusUpdate took
> 115587ns
> I0126 21:09:42.875746 823 hierarchical.cpp:886] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 from framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.875794 830 master.cpp:3947] Processing ACKNOWLEDGE call
> 60cc98f4-e6bb-4605-800a-fff974b814da for task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680 on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0
> I0126 21:09:42.876400 830 master.cpp:6511] Removing task 1 with resources
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:42.877115 800 sched.cpp:1907] Asked to stop the driver
> I0126 21:09:42.877461 830 sched.cpp:1147] Stopping framework
> 'aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000'
> I0126 21:09:42.877835 830 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: 60cc98f4-e6bb-4605-800a-fff974b814da) for task
> 1 of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.878064 830 status_update_manager.cpp:528] Cleaning up status
> update stream for task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.878108 820 master.cpp:5921] Processing TEARDOWN call for
> framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:42.878149 820 master.cpp:5933] Removing framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 (default) at
> scheduler-f9abb9e4-03fb-4fa1-9985-fd85cbf64e24@172.17.0.5:52680
> I0126 21:09:42.878418 820 master.cpp:6540] Removing executor 'default' with
> resources of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 on slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:42.878800 826 hierarchical.cpp:375] Deactivated framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.878901 826 slave.cpp:2078] Asked to shut down framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 by master@172.17.0.5:52680
> I0126 21:09:42.878938 826 slave.cpp:2103] Shutting down framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.879016 826 slave.cpp:4128] Shutting down executor 'default'
> of framework aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 at
> executor(74)@172.17.0.5:52680
> I0126 21:09:42.880188 826 slave.cpp:2411] Status update manager
> successfully handled status update acknowledgement (UUID:
> 60cc98f4-e6bb-4605-800a-fff974b814da) for task 1 of framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.880218 831 hierarchical.cpp:326] Removed framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000
> I0126 21:09:42.880246 826 slave.cpp:5632] Completing task 1
> I0126 21:09:42.880272 831 exec.cpp:381] Executor asked to shutdown
> I0126 21:09:42.880306 831 exec.cpp:396] Executor::shutdown took 18588ns
> I0126 21:09:42.880478 831 slave.cpp:3481] executor(74)@172.17.0.5:52680
> exited
> I0126 21:09:42.882047 823 process.cpp:3141] Handling HTTP event for process
> 'master' with path: '/master/state'
> I0126 21:09:42.882660 823 http.cpp:503] HTTP GET for /master/state from
> 172.17.0.5:42889
> I0126 21:09:42.890214 800 slave.cpp:667] Slave terminating
> I0126 21:09:42.890296 800 slave.cpp:2078] Asked to shut down framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 by @0.0.0.0:0
> W0126 21:09:42.890332 800 slave.cpp:2099] Ignoring shutdown framework
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-0000 because it is terminating
> I0126 21:09:42.891041 819 master.cpp:1172] Slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465) disconnected
> I0126 21:09:42.891074 819 master.cpp:2633] Disconnecting slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:42.892002 819 master.cpp:2652] Deactivating slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 at slave(177)@172.17.0.5:52680
> (c0bf249b6465)
> I0126 21:09:42.892534 829 hierarchical.cpp:556] Slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0 deactivated
> I0126 21:09:42.894146 800 master.cpp:1025] Master terminating
> I0126 21:09:42.895464 823 hierarchical.cpp:502] Removed slave
> aed72a2b-829f-4ec9-b33a-5fac9421d44f-S0
> I0126 21:09:42.918404 800 leveldb.cpp:174] Opened db in 3.079591ms
> I0126 21:09:42.923027 800 leveldb.cpp:181] Compacted db in 4.461306ms
> I0126 21:09:42.923102 800 leveldb.cpp:196] Created db iterator in 24596ns
> I0126 21:09:42.923133 800 leveldb.cpp:202] Seeked to beginning of db in
> 16850ns
> I0126 21:09:42.923235 800 leveldb.cpp:271] Iterated through 3 keys in the
> db in 87510ns
> I0126 21:09:42.923301 800 replica.cpp:779] Replica recovered with log
> positions 3 -> 4 with 0 holes and 0 unlearned
> I0126 21:09:42.924582 834 recover.cpp:447] Starting replica recovery
> I0126 21:09:42.926409 820 recover.cpp:473] Replica is in VOTING status
> I0126 21:09:42.926734 820 recover.cpp:462] Recover process terminated
> I0126 21:09:42.931005 831 master.cpp:374] Master
> 15e9192c-2f14-4492-aa5c-653f8650a2b4 (c0bf249b6465) started on
> 172.17.0.5:52680
> I0126 21:09:42.931041 831 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/a6rJ4B/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="1" --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/a6rJ4B/master" --zk_session_timeout="10secs"
> I0126 21:09:42.931413 831 master.cpp:421] Master only allowing
> authenticated frameworks to register
> I0126 21:09:42.931427 831 master.cpp:426] Master only allowing
> authenticated slaves to register
> I0126 21:09:42.931437 831 credentials.hpp:35] Loading credentials for
> authentication from '/tmp/a6rJ4B/credentials'
> I0126 21:09:42.931824 831 master.cpp:466] Using default 'crammd5'
> authenticator
> I0126 21:09:42.932008 831 master.cpp:535] Using default 'basic' HTTP
> authenticator
> I0126 21:09:42.934044 831 master.cpp:569] Authorization enabled
> I0126 21:09:42.934590 829 hierarchical.cpp:144] Initialized hierarchical
> allocator process
> I0126 21:09:42.934875 829 whitelist_watcher.cpp:77] No whitelist given
> I0126 21:09:42.938220 833 master.cpp:1710] The newly elected leader is
> master@172.17.0.5:52680 with id 15e9192c-2f14-4492-aa5c-653f8650a2b4
> I0126 21:09:42.938351 833 master.cpp:1723] Elected as the leading master!
> I0126 21:09:42.938503 833 master.cpp:1468] Recovering from registrar
> I0126 21:09:42.938890 826 registrar.cpp:307] Recovering registrar
> I0126 21:09:42.939757 820 log.cpp:659] Attempting to start the writer
> I0126 21:09:42.941545 828 replica.cpp:493] Replica received implicit
> promise request from (6093)@172.17.0.5:52680 with proposal 2
> I0126 21:09:42.942541 828 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 950389ns
> I0126 21:09:42.942579 828 replica.cpp:342] Persisted promised to 2
> I0126 21:09:42.943657 828 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0126 21:09:42.944149 828 log.cpp:675] Writer started with ending position 4
> I0126 21:09:42.945760 823 leveldb.cpp:436] Reading position from leveldb
> took 96374ns
> I0126 21:09:42.946051 823 leveldb.cpp:436] Reading position from leveldb
> took 111757ns
> I0126 21:09:42.948451 823 registrar.cpp:340] Successfully fetched the
> registry (300B) in 9.444864ms
> I0126 21:09:42.948943 823 registrar.cpp:439] Applied 1 operations in
> 66331ns; attempting to update the 'registry'
> I0126 21:09:42.950263 834 log.cpp:683] Attempting to append 339 bytes to
> the log
> I0126 21:09:42.950664 834 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 5
> I0126 21:09:42.952014 834 replica.cpp:537] Replica received write request
> for position 5 from (6094)@172.17.0.5:52680
> I0126 21:09:42.952857 834 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 705572ns
> I0126 21:09:42.952991 834 replica.cpp:712] Persisted action at 5
> I0126 21:09:42.954583 828 replica.cpp:691] Replica received learned notice
> for position 5 from @0.0.0.0:0
> I0126 21:09:42.955358 828 leveldb.cpp:341] Persisting action (360 bytes) to
> leveldb took 473678ns
> I0126 21:09:42.955389 828 replica.cpp:712] Persisted action at 5
> I0126 21:09:42.955412 828 replica.cpp:697] Replica learned APPEND action at
> position 5
> I0126 21:09:42.957082 828 registrar.cpp:484] Successfully updated the
> 'registry' in 7.984896ms
> I0126 21:09:42.957293 828 registrar.cpp:370] Successfully recovered
> registrar
> I0126 21:09:42.957677 830 log.cpp:702] Attempting to truncate the log to 5
> I0126 21:09:42.958268 826 master.cpp:1520] Recovered 1 slaves from the
> Registry (300B) ; allowing 10mins for slaves to re-register
> I0126 21:09:42.958691 820 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 6
> I0126 21:09:42.960016 820 replica.cpp:537] Replica received write request
> for position 6 from (6095)@172.17.0.5:52680
> I0126 21:09:42.958310 825 hierarchical.cpp:171] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0126 21:09:42.962357 820 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 2.201935ms
> I0126 21:09:42.962469 820 replica.cpp:712] Persisted action at 6
> I0126 21:09:42.963702 820 replica.cpp:691] Replica received learned notice
> for position 6 from @0.0.0.0:0
> I0126 21:09:42.964346 820 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 397693ns
> I0126 21:09:42.964522 820 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 44427ns
> I0126 21:09:42.964649 820 replica.cpp:712] Persisted action at 6
> I0126 21:09:42.964761 820 replica.cpp:697] Replica learned TRUNCATE action
> at position 6
> I0126 21:09:42.979033 832 slave.cpp:192] Slave started on
> 178)@172.17.0.5:52680
> I0126 21:09:42.979267 832 slave.cpp:193] 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_MaxCompletedTasksPerFrameworkFlag_Nqu0t7/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_MaxCompletedTasksPerFrameworkFlag_Nqu0t7/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="true"
> --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_MaxCompletedTasksPerFrameworkFlag_Nqu0t7"
> I0126 21:09:42.980240 832 credentials.hpp:83] Loading credential for
> authentication from
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_Nqu0t7/credential'
> I0126 21:09:42.980603 832 slave.cpp:323] Slave using credential for:
> test-principal
> I0126 21:09:42.980914 832 resources.cpp:564] Parsing resources as JSON
> failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0126 21:09:42.981576 832 slave.cpp:463] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0126 21:09:42.981750 832 slave.cpp:471] Slave attributes: [ ]
> I0126 21:09:42.981861 832 slave.cpp:476] Slave hostname: c0bf249b6465
> I0126 21:09:42.983530 819 state.cpp:58] Recovering state from
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_Nqu0t7/meta'
> I0126 21:09:42.985999 830 status_update_manager.cpp:200] Recovering status
> update manager
> I0126 21:09:42.987390 828 slave.cpp:4495] Finished recovery
> I0126 21:09:42.988143 828 slave.cpp:4667] Querying resource estimator for
> oversubscribable resources
> I0126 21:09:42.989017 828 slave.cpp:795] New master detected at
> master@172.17.0.5:52680
> I0126 21:09:42.989253 828 slave.cpp:858] Authenticating with master
> master@172.17.0.5:52680
> I0126 21:09:42.989382 828 slave.cpp:863] Using default CRAM-MD5
> authenticatee
> I0126 21:09:42.989730 828 slave.cpp:831] Detecting new master
> I0126 21:09:42.990000 828 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0126 21:09:42.990447 834 status_update_manager.cpp:174] Pausing sending
> status updates
> I0126 21:09:42.990599 826 authenticatee.cpp:121] Creating new client SASL
> connection
> I0126 21:09:42.991245 826 master.cpp:5521] Authenticating
> slave(178)@172.17.0.5:52680
> I0126 21:09:42.991564 822 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(425)@172.17.0.5:52680
> I0126 21:09:42.992164 822 authenticator.cpp:98] Creating new server SASL
> connection
> I0126 21:09:42.992552 833 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0126 21:09:42.992677 833 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0126 21:09:42.993134 822 authenticator.cpp:203] Received SASL
> authentication start
> I0126 21:09:42.993288 822 authenticator.cpp:325] Authentication requires
> more steps
> I0126 21:09:42.993563 822 authenticatee.cpp:258] Received SASL
> authentication step
> I0126 21:09:42.993832 822 authenticator.cpp:231] Received SASL
> authentication step
> I0126 21:09:42.993957 822 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0126 21:09:42.994071 822 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0126 21:09:42.994221 822 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0126 21:09:42.994369 822 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0126 21:09:42.994487 822 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:42.994599 822 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:42.994724 822 authenticator.cpp:317] Authentication success
> I0126 21:09:42.995069 831 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at slave(178)@172.17.0.5:52680
> I0126 21:09:42.995239 829 authenticatee.cpp:298] Authentication success
> I0126 21:09:42.995648 822 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(425)@172.17.0.5:52680
> I0126 21:09:42.980924 800 sched.cpp:222] Version: 0.27.0
> I0126 21:09:43.002167 826 sched.cpp:326] New master detected at
> master@172.17.0.5:52680
> I0126 21:09:43.002358 826 sched.cpp:382] Authenticating with master
> master@172.17.0.5:52680
> I0126 21:09:43.002382 826 sched.cpp:389] Using default CRAM-MD5
> authenticatee
> I0126 21:09:43.002686 834 authenticatee.cpp:121] Creating new client SASL
> connection
> I0126 21:09:43.003042 828 slave.cpp:926] Successfully authenticated with
> master master@172.17.0.5:52680
> I0126 21:09:43.003185 828 slave.cpp:1320] Will retry registration in
> 377848ns if necessary
> I0126 21:09:43.003350 834 master.cpp:5521] Authenticating
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680
> I0126 21:09:43.003855 834 master.cpp:4235] Registering slave at
> slave(178)@172.17.0.5:52680 (c0bf249b6465) with id
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0
> I0126 21:09:43.004108 826 authenticator.cpp:413] Starting authentication
> session for crammd5_authenticatee(426)@172.17.0.5:52680
> I0126 21:09:43.004689 831 slave.cpp:1320] Will retry registration in
> 6.685453ms if necessary
> I0126 21:09:43.004804 834 registrar.cpp:439] Applied 1 operations in
> 153529ns; attempting to update the 'registry'
> I0126 21:09:43.004906 831 master.cpp:4223] Ignoring register slave message
> from slave(178)@172.17.0.5:52680 (c0bf249b6465) as admission is already in
> progress
> I0126 21:09:43.005156 826 authenticator.cpp:98] Creating new server SASL
> connection
> I0126 21:09:43.005390 826 authenticatee.cpp:212] Received SASL
> authentication mechanisms: CRAM-MD5
> I0126 21:09:43.005421 826 authenticatee.cpp:238] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0126 21:09:43.005502 826 authenticator.cpp:203] Received SASL
> authentication start
> I0126 21:09:43.005571 826 authenticator.cpp:325] Authentication requires
> more steps
> I0126 21:09:43.006242 831 authenticatee.cpp:258] Received SASL
> authentication step
> I0126 21:09:43.006343 831 authenticator.cpp:231] Received SASL
> authentication step
> I0126 21:09:43.006376 831 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0126 21:09:43.006391 831 auxprop.cpp:179] Looking up auxiliary property
> '*userPassword'
> I0126 21:09:43.006436 831 auxprop.cpp:179] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0126 21:09:43.006469 831 auxprop.cpp:107] Request to lookup properties for
> user: 'test-principal' realm: 'c0bf249b6465' server FQDN: 'c0bf249b6465'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0126 21:09:43.006482 831 auxprop.cpp:129] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:43.006492 831 auxprop.cpp:129] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0126 21:09:43.006510 831 authenticator.cpp:317] Authentication success
> I0126 21:09:43.006681 822 authenticator.cpp:431] Authentication session
> cleanup for crammd5_authenticatee(426)@172.17.0.5:52680
> I0126 21:09:43.006777 831 master.cpp:5551] Successfully authenticated
> principal 'test-principal' at
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680
> I0126 21:09:43.007014 831 log.cpp:683] Attempting to append 505 bytes to
> the log
> I0126 21:09:43.007333 826 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 7
> I0126 21:09:43.007648 834 authenticatee.cpp:298] Authentication success
> I0126 21:09:43.008322 834 sched.cpp:471] Successfully authenticated with
> master master@172.17.0.5:52680
> I0126 21:09:43.008419 834 sched.cpp:780] Sending SUBSCRIBE call to
> master@172.17.0.5:52680
> I0126 21:09:43.008625 834 sched.cpp:813] Will retry registration in
> 1.787407952secs if necessary
> I0126 21:09:43.008852 831 master.cpp:2278] Received SUBSCRIBE call for
> framework 'default' at
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680
> I0126 21:09:43.010007 831 master.cpp:1749] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0126 21:09:43.010526 831 master.cpp:2349] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0126 21:09:43.009491 829 replica.cpp:537] Replica received write request
> for position 7 from (6100)@172.17.0.5:52680
> I0126 21:09:43.011543 831 hierarchical.cpp:265] Added framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000
> I0126 21:09:43.011672 829 leveldb.cpp:341] Persisting action (524 bytes) to
> leveldb took 884764ns
> I0126 21:09:43.011848 829 replica.cpp:712] Persisted action at 7
> I0126 21:09:43.012418 831 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:43.013181 833 replica.cpp:691] Replica received learned notice
> for position 7 from @0.0.0.0:0
> I0126 21:09:43.013352 822 slave.cpp:1320] Will retry registration in
> 24.22787ms if necessary
> I0126 21:09:43.014257 833 leveldb.cpp:341] Persisting action (526 bytes) to
> leveldb took 667136ns
> I0126 21:09:43.014287 833 replica.cpp:712] Persisted action at 7
> I0126 21:09:43.014310 833 replica.cpp:697] Replica learned APPEND action at
> position 7
> I0126 21:09:43.014435 822 master.cpp:4223] Ignoring register slave message
> from slave(178)@172.17.0.5:52680 (c0bf249b6465) as admission is already in
> progress
> I0126 21:09:43.013471 831 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:43.014696 831 hierarchical.cpp:1090] Performed allocation for 0
> slaves in 2.333257ms
> I0126 21:09:43.016073 834 sched.cpp:707] Framework registered with
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000
> I0126 21:09:43.016252 834 sched.cpp:721] Scheduler::registered took 71270ns
> I0126 21:09:43.018067 825 registrar.cpp:484] Successfully updated the
> 'registry' in 13.103872ms
> I0126 21:09:43.018780 829 log.cpp:702] Attempting to truncate the log to 7
> I0126 21:09:43.019740 834 master.cpp:4303] Registered slave
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0 at slave(178)@172.17.0.5:52680
> (c0bf249b6465) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0126 21:09:43.020323 830 hierarchical.cpp:471] Added slave
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0 (c0bf249b6465) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0126 21:09:43.020501 824 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 8
> I0126 21:09:43.021754 824 replica.cpp:537] Replica received write request
> for position 8 from (6101)@172.17.0.5:52680
> I0126 21:09:43.021865 830 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:43.023092 830 hierarchical.cpp:1110] Performed allocation for
> slave 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0 in 2.678988ms
> I0126 21:09:43.022403 827 master.cpp:5350] Sending 1 offers to framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000 (default) at
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
> Function call: resourceOffers(0x7fff89a34060, @0x7f7c5a36b8f0 { 144-byte
> object <50-70 7C-67 7C-7F 00-00 00-00 00-00 00-00 00-00 E0-EF 01-0C 7C-7F
> 00-00 80-F0 01-0C 7C-7F 00-00 B0-89 01-0C 7C-7F 00-00 50-DC 02-0C 7C-7F 00-00
> A0-DC 02-0C 7C-7F 00-00 C0-99 01-0C 7C-7F 00-00 ... 00-00 00-00 00-00 00-00
> 00-00 00-00 00-00 00-00 00-00 00-00 74-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-00
> 1F-00 00-00> })
> Stack trace:
> I0126 21:09:43.023912 819 sched.cpp:877] Scheduler::resourceOffers took
> 124340ns
> I0126 21:09:43.022032 825 slave.cpp:970] Registered with master
> master@172.17.0.5:52680; given slave ID
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0
> I0126 21:09:43.024173 825 fetcher.cpp:81] Clearing fetcher cache
> I0126 21:09:43.024377 822 status_update_manager.cpp:181] Resuming sending
> status updates
> I0126 21:09:43.024389 824 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 1.732284ms
> I0126 21:09:43.024425 824 replica.cpp:712] Persisted action at 8
> I0126 21:09:43.024727 825 slave.cpp:993] Checkpointing SlaveInfo to
> '/tmp/MasterTest_MaxCompletedTasksPerFrameworkFlag_Nqu0t7/meta/slaves/15e9192c-2f14-4492-aa5c-653f8650a2b4-S0/slave.info'
> I0126 21:09:43.025629 822 replica.cpp:691] Replica received learned notice
> for position 8 from @0.0.0.0:0
> I0126 21:09:43.026281 822 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 615006ns
> I0126 21:09:43.026361 822 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 47734ns
> I0126 21:09:43.026389 822 replica.cpp:712] Persisted action at 8
> I0126 21:09:43.026414 822 replica.cpp:697] Replica learned TRUNCATE action
> at position 8
> I0126 21:09:43.027241 825 slave.cpp:1029] Forwarding total oversubscribed
> resources
> I0126 21:09:43.027441 825 slave.cpp:3435] Received ping from
> slave-observer(182)@172.17.0.5:52680
> I0126 21:09:43.027611 827 master.cpp:4644] Received update of slave
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0 at slave(178)@172.17.0.5:52680
> (c0bf249b6465) with total oversubscribed resources
> I0126 21:09:43.028612 827 hierarchical.cpp:527] Slave
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0 (c0bf249b6465) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0126 21:09:43.028941 827 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:43.029065 827 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:43.029175 827 hierarchical.cpp:1110] Performed allocation for
> slave 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0 in 436241ns
> I0126 21:09:43.935612 827 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:43.935693 827 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:43.935722 827 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 395245ns
> I0126 21:09:44.936697 820 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:44.936779 820 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:44.936815 820 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 422818ns
> 2016-01-26
> 21:09:45,800:800(0x7f7b957b6700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36129] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0126 21:09:45.938558 830 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:45.938639 830 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:45.938670 830 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 403168ns
> I0126 21:09:46.940754 821 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:46.941277 821 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:46.941325 821 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 966993ns
> I0126 21:09:47.943084 823 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:47.943166 823 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:47.943200 823 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 461339ns
> I0126 21:09:48.944010 824 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:48.944093 824 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:48.944133 824 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 451705ns
> 2016-01-26
> 21:09:49,137:800(0x7f7b957b6700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36129] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0126 21:09:49.945228 819 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:49.945312 819 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:49.945348 819 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 429841ns
> I0126 21:09:50.946374 829 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:50.946455 829 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:50.946481 829 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 381187ns
> I0126 21:09:51.948294 819 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:51.948375 819 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:51.948410 819 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 417538ns
> 2016-01-26
> 21:09:52,473:800(0x7f7b957b6700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36129] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0126 21:09:52.949796 824 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:52.950109 824 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:52.950278 824 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 784644ns
> I0126 21:09:53.951604 831 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:53.951794 831 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:53.951942 831 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 621967ns
> I0126 21:09:54.952677 833 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:54.953052 833 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:54.953219 833 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 833911ns
> 2016-01-26
> 21:09:55,809:800(0x7f7b957b6700):ZOO_ERROR@handle_socket_error_msg@1697:
> Socket [127.0.0.1:36129] zk retcode=-4, errno=111(Connection refused): server
> refused to accept the client
> I0126 21:09:55.954888 827 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:55.955117 827 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:55.955276 827 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 667701ns
> I0126 21:09:56.956389 820 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:56.957080 820 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:56.957463 820 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 1.598333ms
> I0126 21:09:57.959658 826 hierarchical.cpp:1355] No resources available to
> allocate!
> I0126 21:09:57.959846 826 hierarchical.cpp:1450] No inverse offers to send
> out!
> I0126 21:09:57.959996 826 hierarchical.cpp:1090] Performed allocation for 1
> slaves in 631969ns
> I0126 21:09:57.990658 819 slave.cpp:4667] Querying resource estimator for
> oversubscribable resources
> I0126 21:09:57.990924 819 slave.cpp:4681] Received oversubscribable
> resources from the resource estimator
> I0126 21:09:58.020987 819 slave.cpp:3435] Received ping from
> slave-observer(182)@172.17.0.5:52680
> ../../src/tests/master_tests.cpp:4031: Failure
> Failed to wait 15secs for offers
> I0126 21:09:58.028162 829 master.cpp:1211] Framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000 (default) at
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680 disconnected
> ../../src/tests/master_tests.cpp:4027: Failure
> Actual function call count doesn't match EXPECT_CALL(sched,
> resourceOffers(&schedDriver, _))...
> Expected: to be called at least once
> I Actual: never called - unsatisfied and active
> 0126 21:09:58.028687 829 master.cpp:2574] Disconnecting framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000 (default) at
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680
> ../../src/tests/master_tests.cpp:4008: Failure
> Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _,
> _, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> I0126 21:09:58.028916 829 master.cpp:2598] Deactivating framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000 (default) at
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680
> I0126 21:09:58.029136 821 hierarchical.cpp:375] Deactivated framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000
> W0126 21:09:58.030082 829 master.hpp:1761] Master attempted to send message
> to disconnected framework 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000 (default)
> at scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680
> I0126 21:09:58.030287 821 hierarchical.cpp:886] Recovered cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0 from framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000
> I0126 21:09:58.030984 829 master.cpp:1235] Giving framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000 (default) at
> scheduler-9664491f-dd6b-41ba-b27f-3704b5bace6f@172.17.0.5:52680 0ns to
> failover
> I0126 21:09:58.031497 829 master.cpp:1025] Master terminating
> I0126 21:09:58.032500 822 hierarchical.cpp:502] Removed slave
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-S0
> I0126 21:09:58.032694 822 hierarchical.cpp:326] Removed framework
> 15e9192c-2f14-4492-aa5c-653f8650a2b4-0000
> I0126 21:09:58.033149 834 slave.cpp:3481] master@172.17.0.5:52680 exited
> W0126 21:09:58.033179 834 slave.cpp:3484] Master disconnected! Waiting for
> a new master to be elected
> I0126 21:09:58.043854 800 slave.cpp:667] Slave terminating
> [ FAILED ] MasterTest.MaxCompletedTasksPerFrameworkFlag (16205 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
