[MESOS-4518] MasterTest.MaxCompletedTasksPerFrameworkFlag is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 0.26.0
Fix Version/s: 0.24.2, 0.25.1, 0.26.1, 0.27.0
Component/s: test
Labels:
Environment:

CentOS 7 with gcc

Epic Link:
flaky
Sprint:
Mesosphere Sprint 27

Description

Just observed this on ASF CI, CentOS 7 with gcc:

[ 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)

Attachments

Issue Links

duplicates

MESOS-4525 MasterTest.MaxCompletedTasksPerFrameworkFlag is flaky

Resolved

Activity

People

Assignee:: Kevin Klues

Reporter:: Greg Mann

Shepherd:: Benjamin Mahler

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 26/Jan/16 21:46

Updated:: 26/Apr/17 17:00

Resolved:: 29/Jan/16 21:16