[ https://issues.apache.org/jira/browse/MESOS-3422?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Guangya Liu updated MESOS-3422: ------------------------------- Description: [==========] Running 1 test from 1 test case. [----------] Global test environment set-up. [----------] 1 test from MasterSlaveReconciliationTest [ RUN ] MasterSlaveReconciliationTest.ReconcileLostTask Using temporary directory '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn' I0915 22:28:40.800787 3733 leveldb.cpp:176] Opened db in 252.206266ms I0915 22:28:40.851069 3733 leveldb.cpp:183] Compacted db in 50.197346ms I0915 22:28:40.851210 3733 leveldb.cpp:198] Created db iterator in 63324ns I0915 22:28:40.851256 3733 leveldb.cpp:204] Seeked to beginning of db in 4562ns I0915 22:28:40.851286 3733 leveldb.cpp:273] Iterated through 0 keys in the db in 322ns I0915 22:28:40.871953 3733 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0915 22:28:40.886368 3756 recover.cpp:449] Starting replica recovery I0915 22:28:40.903333 3756 recover.cpp:475] Replica is in EMPTY status I0915 22:28:40.916332 3759 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request I0915 22:28:40.917351 3756 recover.cpp:195] Received a recover response from a replica in EMPTY status I0915 22:28:40.918557 3755 recover.cpp:566] Updating replica status to STARTING I0915 22:28:40.928189 3759 master.cpp:380] Master 20150915-222840-16842879-54960-3733 (devstack007.cn.ibm.com) started on 127.0.1.1:54960 I0915 22:28:40.928261 3759 master.cpp:382] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn/credentials" --framework_sorter="drf" --help="false" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn/master" --zk_session_timeout="10secs" I0915 22:28:40.993895 3759 master.cpp:427] Master only allowing authenticated frameworks to register I0915 22:28:40.993962 3759 master.cpp:432] Master only allowing authenticated slaves to register I0915 22:28:40.994010 3759 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn/credentials' I0915 22:28:40.994776 3759 master.cpp:471] Using default 'crammd5' authenticator I0915 22:28:40.995053 3759 authenticator.cpp:512] Initializing server SASL I0915 22:28:41.009496 3757 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 90.341573ms I0915 22:28:41.009570 3757 replica.cpp:323] Persisted replica status to STARTING I0915 22:28:41.010040 3756 recover.cpp:475] Replica is in STARTING status I0915 22:28:41.011255 3757 replica.cpp:641] Replica in STARTING status received a broadcasted recover request I0915 22:28:41.011551 3752 recover.cpp:195] Received a recover response from a replica in STARTING status I0915 22:28:41.012073 3756 recover.cpp:566] Updating replica status to VOTING I0915 22:28:41.084720 3753 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 72.469042ms I0915 22:28:41.084803 3753 replica.cpp:323] Persisted replica status to VOTING I0915 22:28:41.084935 3752 recover.cpp:580] Successfully joined the Paxos group I0915 22:28:41.085227 3752 recover.cpp:464] Recover process terminated I0915 22:28:41.191287 3759 auxprop.cpp:66] Initialized in-memory auxiliary property plugin I0915 22:28:41.191455 3759 master.cpp:508] Authorization enabled I0915 22:28:41.192039 3758 hierarchical.hpp:408] Initialized hierarchical allocator process I0915 22:28:41.210978 3752 whitelist_watcher.cpp:79] No whitelist given I0915 22:28:41.226894 3757 master.cpp:1605] The newly elected leader is master@127.0.1.1:54960 with id 20150915-222840-16842879-54960-3733 I0915 22:28:41.227022 3757 master.cpp:1618] Elected as the leading master! I0915 22:28:41.227073 3757 master.cpp:1378] Recovering from registrar I0915 22:28:41.227442 3756 registrar.cpp:309] Recovering registrar I0915 22:28:41.228864 3759 log.cpp:661] Attempting to start the writer I0915 22:28:41.231155 3754 replica.cpp:477] Replica received implicit promise request with proposal 1 I0915 22:28:41.276180 3754 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 44.960628ms I0915 22:28:41.276265 3754 replica.cpp:345] Persisted promised to 1 I0915 22:28:41.277185 3755 coordinator.cpp:231] Coordinator attemping to fill missing position I0915 22:28:41.279559 3755 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2 I0915 22:28:41.317904 3755 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 38.28625ms I0915 22:28:41.317952 3755 replica.cpp:679] Persisted action at 0 I0915 22:28:41.318975 3756 replica.cpp:511] Replica received write request for position 0 I0915 22:28:41.319077 3756 leveldb.cpp:438] Reading position from leveldb took 48432ns I0915 22:28:41.351290 3756 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 32.131668ms I0915 22:28:41.351372 3756 replica.cpp:679] Persisted action at 0 I0915 22:28:41.352147 3755 replica.cpp:658] Replica received learned notice for position 0 I0915 22:28:41.384781 3755 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 32.568205ms I0915 22:28:41.384858 3755 replica.cpp:679] Persisted action at 0 I0915 22:28:41.384902 3755 replica.cpp:664] Replica learned NOP action at position 0 I0915 22:28:41.385823 3753 log.cpp:677] Writer started with ending position 0 I0915 22:28:41.388413 3754 leveldb.cpp:438] Reading position from leveldb took 41960ns I0915 22:28:41.391221 3759 registrar.cpp:342] Successfully fetched the registry (0B) in 163.655936ms I0915 22:28:41.391530 3759 registrar.cpp:441] Applied 1 operations in 83084ns; attempting to update the 'registry' I0915 22:28:41.395333 3752 log.cpp:685] Attempting to append 188 bytes to the log I0915 22:28:41.395625 3757 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1 I0915 22:28:41.396404 3753 replica.cpp:511] Replica received write request for position 1 I0915 22:28:41.434862 3753 leveldb.cpp:343] Persisting action (207 bytes) to leveldb took 38.376695ms I0915 22:28:41.434942 3753 replica.cpp:679] Persisted action at 1 I0915 22:28:41.435797 3758 replica.cpp:658] Replica received learned notice for position 1 I0915 22:28:41.484905 3758 leveldb.cpp:343] Persisting action (209 bytes) to leveldb took 49.03218ms I0915 22:28:41.484977 3758 replica.cpp:679] Persisted action at 1 I0915 22:28:41.485021 3758 replica.cpp:664] Replica learned APPEND action at position 1 I0915 22:28:41.486634 3759 registrar.cpp:486] Successfully updated the 'registry' in 94.96704ms I0915 22:28:41.486788 3759 registrar.cpp:372] Successfully recovered registrar I0915 22:28:41.486871 3752 log.cpp:704] Attempting to truncate the log to 1 I0915 22:28:41.487041 3753 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2 I0915 22:28:41.487397 3758 master.cpp:1415] Recovered 0 slaves from the Registry (149B) ; allowing 10mins for slaves to re-register I0915 22:28:41.488390 3754 replica.cpp:511] Replica received write request for position 2 I0915 22:28:41.518287 3754 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 29.818009ms I0915 22:28:41.518383 3754 replica.cpp:679] Persisted action at 2 I0915 22:28:41.519301 3753 replica.cpp:658] Replica received learned notice for position 2 I0915 22:28:41.551661 3753 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 32.172645ms I0915 22:28:41.551758 3753 leveldb.cpp:401] Deleting ~1 keys from leveldb took 45547ns I0915 22:28:41.551798 3753 replica.cpp:679] Persisted action at 2 I0915 22:28:41.551862 3753 replica.cpp:664] Replica learned TRUNCATE action at position 2 I0915 22:28:41.582856 3733 containerizer.cpp:160] Using isolation: posix/cpu,posix/mem,filesystem/posix I0915 22:28:41.612773 3752 slave.cpp:190] Slave started on 1)@127.0.1.1:54960 I0915 22:28:41.612828 3752 slave.cpp:191] Flags at startup: --appc_provisioner_backend="copy" --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/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/home/gyliu/src/mesos/bug-fix/mesos/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" --resource_monitoring_interval="1secs" --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" --version="false" --work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7" I0915 22:28:41.613301 3752 credentials.hpp:85] Loading credential for authentication from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/credential' I0915 22:28:41.613534 3752 slave.cpp:321] Slave using credential for: test-principal I0915 22:28:41.614586 3752 slave.cpp:354] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0915 22:28:41.614718 3752 slave.cpp:384] Slave hostname: devstack007.cn.ibm.com I0915 22:28:41.614749 3752 slave.cpp:389] Slave checkpoint: true I0915 22:28:41.616605 3756 state.cpp:54] Recovering state from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/meta' I0915 22:28:41.617005 3756 status_update_manager.cpp:202] Recovering status update manager I0915 22:28:41.617219 3756 containerizer.cpp:396] Recovering containerizer I0915 22:28:41.618137 3733 sched.cpp:164] Version: 0.25.0 I0915 22:28:41.620059 3752 sched.cpp:262] New master detected at master@127.0.1.1:54960 I0915 22:28:41.620291 3752 sched.cpp:318] Authenticating with master master@127.0.1.1:54960 I0915 22:28:41.620337 3752 sched.cpp:325] Using default CRAM-MD5 authenticatee I0915 22:28:41.620400 3758 slave.cpp:4077] Finished recovery I0915 22:28:41.620708 3759 authenticatee.cpp:91] Initializing client SASL I0915 22:28:41.620842 3758 slave.cpp:4234] Querying resource estimator for oversubscribable resources I0915 22:28:41.620873 3759 authenticatee.cpp:115] Creating new client SASL connection I0915 22:28:41.621410 3752 master.cpp:5089] Authenticating scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 I0915 22:28:41.621544 3757 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(1)@127.0.1.1:54960 I0915 22:28:41.621572 3758 slave.cpp:692] New master detected at master@127.0.1.1:54960 I0915 22:28:41.621656 3758 slave.cpp:755] Authenticating with master master@127.0.1.1:54960 I0915 22:28:41.621686 3758 slave.cpp:760] Using default CRAM-MD5 authenticatee I0915 22:28:41.621772 3752 status_update_manager.cpp:176] Pausing sending status updates I0915 22:28:41.621888 3755 authenticatee.cpp:115] Creating new client SASL connection I0915 22:28:41.621942 3758 slave.cpp:728] Detecting new master I0915 22:28:41.622141 3758 slave.cpp:4248] Received oversubscribable resources from the resource estimator I0915 22:28:41.621975 3753 authenticator.cpp:92] Creating new server SASL connection I0915 22:28:41.622253 3754 master.cpp:5089] Authenticating slave(1)@127.0.1.1:54960 I0915 22:28:41.622418 3756 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(2)@127.0.1.1:54960 I0915 22:28:41.622560 3757 authenticator.cpp:92] Creating new server SASL connection I0915 22:28:41.624449 3759 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 I0915 22:28:41.624451 3755 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 I0915 22:28:41.624485 3759 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' I0915 22:28:41.624511 3755 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' I0915 22:28:41.624595 3759 authenticator.cpp:197] Received SASL authentication start I0915 22:28:41.624606 3755 authenticator.cpp:197] Received SASL authentication start I0915 22:28:41.624666 3759 authenticator.cpp:319] Authentication requires more steps I0915 22:28:41.624698 3755 authenticator.cpp:319] Authentication requires more steps I0915 22:28:41.624742 3759 authenticatee.cpp:252] Received SASL authentication step I0915 22:28:41.624788 3755 authenticatee.cpp:252] Received SASL authentication step I0915 22:28:41.624846 3759 authenticator.cpp:225] Received SASL authentication step I0915 22:28:41.624876 3759 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0915 22:28:41.624879 3755 authenticator.cpp:225] Received SASL authentication step I0915 22:28:41.624898 3759 auxprop.cpp:174] Looking up auxiliary property '*userPassword' I0915 22:28:41.624927 3755 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0915 22:28:41.624956 3755 auxprop.cpp:174] Looking up auxiliary property '*userPassword' I0915 22:28:41.625015 3759 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0915 22:28:41.625020 3755 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0915 22:28:41.625049 3759 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0915 22:28:41.625067 3759 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0915 22:28:41.625071 3755 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0915 22:28:41.625080 3759 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0915 22:28:41.625102 3755 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0915 22:28:41.625118 3759 authenticator.cpp:311] Authentication success I0915 22:28:41.625123 3755 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0915 22:28:41.625154 3755 authenticator.cpp:311] Authentication success I0915 22:28:41.625191 3754 authenticatee.cpp:292] Authentication success I0915 22:28:41.625288 3753 authenticatee.cpp:292] Authentication success I0915 22:28:41.625375 3752 master.cpp:5119] Successfully authenticated principal 'test-principal' at scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 I0915 22:28:41.625401 3759 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(1)@127.0.1.1:54960 I0915 22:28:41.625497 3754 sched.cpp:407] Successfully authenticated with master master@127.0.1.1:54960 I0915 22:28:41.625535 3754 sched.cpp:714] Sending SUBSCRIBE call to master@127.0.1.1:54960 I0915 22:28:41.625500 3752 master.cpp:5119] Successfully authenticated principal 'test-principal' at slave(1)@127.0.1.1:54960 I0915 22:28:41.625704 3759 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(2)@127.0.1.1:54960 I0915 22:28:41.625695 3754 sched.cpp:747] Will retry registration in 810.177326ms if necessary I0915 22:28:41.625833 3755 master.cpp:2174] Received SUBSCRIBE call for framework 'default' at scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 I0915 22:28:41.625833 3758 slave.cpp:823] Successfully authenticated with master master@127.0.1.1:54960 I0915 22:28:41.625954 3755 master.cpp:1644] Authorizing framework principal 'test-principal' to receive offers for role '*' I0915 22:28:41.626005 3758 slave.cpp:1217] Will retry registration in 1.558741ms if necessary I0915 22:28:41.628494 3758 slave.cpp:1217] Will retry registration in 4.690825ms if necessary I0915 22:28:41.634006 3756 slave.cpp:1217] Will retry registration in 12.908225ms if necessary I0915 22:28:41.636726 3755 master.cpp:3816] Registering slave at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) with id 20150915-222840-16842879-54960-3733-S0 I0915 22:28:41.637073 3755 master.cpp:2244] Subscribing framework default with checkpointing disabled and capabilities [ ] I0915 22:28:41.637322 3753 registrar.cpp:441] Applied 1 operations in 55510ns; attempting to update the 'registry' I0915 22:28:41.637547 3752 hierarchical.hpp:453] Added framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.637742 3755 master.cpp:3804] Ignoring register slave message from slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) as admission is already in progress I0915 22:28:41.637774 3759 sched.cpp:641] Framework registered with 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.637926 3752 hierarchical.hpp:1147] No resources available to allocate! I0915 22:28:41.638077 3752 hierarchical.hpp:1230] No inverse offers to send out! I0915 22:28:41.638087 3755 master.cpp:3804] Ignoring register slave message from slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) as admission is already in progress I0915 22:28:41.638108 3752 hierarchical.hpp:1047] Performed allocation for 0 slaves in 202137ns I0915 22:28:41.638044 3759 sched.cpp:655] Scheduler::registered took 39399ns I0915 22:28:41.640064 3754 log.cpp:685] Attempting to append 366 bytes to the log I0915 22:28:41.640266 3755 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3 I0915 22:28:41.640923 3756 replica.cpp:511] Replica received write request for position 3 I0915 22:28:41.647588 3752 slave.cpp:1217] Will retry registration in 148.576472ms if necessary I0915 22:28:41.647784 3758 master.cpp:3804] Ignoring register slave message from slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) as admission is already in progress I0915 22:28:41.693835 3756 leveldb.cpp:343] Persisting action (385 bytes) to leveldb took 52.865341ms I0915 22:28:41.693887 3756 replica.cpp:679] Persisted action at 3 I0915 22:28:41.694504 3752 replica.cpp:658] Replica received learned notice for position 3 I0915 22:28:41.727273 3752 leveldb.cpp:343] Persisting action (387 bytes) to leveldb took 32.694232ms I0915 22:28:41.727345 3752 replica.cpp:679] Persisted action at 3 I0915 22:28:41.727392 3752 replica.cpp:664] Replica learned APPEND action at position 3 I0915 22:28:41.728603 3754 registrar.cpp:486] Successfully updated the 'registry' in 91.195136ms I0915 22:28:41.728809 3755 log.cpp:704] Attempting to truncate the log to 3 I0915 22:28:41.728914 3754 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4 I0915 22:28:41.729423 3753 replica.cpp:511] Replica received write request for position 4 I0915 22:28:41.729729 3755 slave.cpp:3105] Received ping from slave-observer(1)@127.0.1.1:54960 I0915 22:28:41.729907 3758 master.cpp:3884] Registered slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0915 22:28:41.730042 3755 hierarchical.hpp:612] Added slave 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) I0915 22:28:41.730104 3754 slave.cpp:867] Registered with master master@127.0.1.1:54960; given slave ID 20150915-222840-16842879-54960-3733-S0 I0915 22:28:41.730140 3754 fetcher.cpp:77] Clearing fetcher cache I0915 22:28:41.730262 3757 status_update_manager.cpp:183] Resuming sending status updates I0915 22:28:41.730599 3755 hierarchical.hpp:1230] No inverse offers to send out! I0915 22:28:41.730633 3755 hierarchical.hpp:1065] Performed allocation for slave 20150915-222840-16842879-54960-3733-S0 in 548692ns I0915 22:28:41.731081 3759 master.cpp:4918] Sending 1 offers to framework 20150915-222840-16842879-54960-3733-0000 (default) at scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 I0915 22:28:41.731506 3759 sched.cpp:811] Scheduler::resourceOffers took 76181ns I0915 22:28:41.733994 3758 master.cpp:2878] Processing ACCEPT call for offers: [ 20150915-222840-16842879-54960-3733-O0 ] on slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) for framework 20150915-222840-16842879-54960-3733-0000 (default) at scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 I0915 22:28:41.734100 3758 master.cpp:2682] Authorizing framework principal 'test-principal' to launch task 1 as user 'gyliu' W0915 22:28:41.736322 3758 validation.cpp:419] 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. W0915 22:28:41.736408 3758 validation.cpp:431] 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. I0915 22:28:41.737035 3758 master.hpp:176] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) I0915 22:28:41.737259 3758 master.cpp:3208] Launching task 1 of framework 20150915-222840-16842879-54960-3733-0000 (default) at scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) I0915 22:28:41.820271 3754 slave.cpp:890] Checkpointing SlaveInfo to '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/meta/slaves/20150915-222840-16842879-54960-3733-S0/slave.info' I0915 22:28:41.820550 3754 slave.cpp:926] Forwarding total oversubscribed resources I0915 22:28:41.821171 3756 master.cpp:4226] Received update of slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) with total oversubscribed resources I0915 22:28:41.821429 3755 hierarchical.hpp:672] Slave 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I0915 22:28:41.821674 3755 hierarchical.hpp:1147] No resources available to allocate! I0915 22:28:41.821709 3755 hierarchical.hpp:1230] No inverse offers to send out! I0915 22:28:41.821738 3755 hierarchical.hpp:1065] Performed allocation for slave 20150915-222840-16842879-54960-3733-S0 in 264094ns I0915 22:28:41.822713 3756 status_update_manager.cpp:176] Pausing sending status updates I0915 22:28:41.822727 3758 slave.cpp:692] New master detected at master@127.0.1.1:54960 I0915 22:28:41.822803 3758 slave.cpp:755] Authenticating with master master@127.0.1.1:54960 I0915 22:28:41.822823 3758 slave.cpp:760] Using default CRAM-MD5 authenticatee I0915 22:28:41.822923 3758 slave.cpp:728] Detecting new master I0915 22:28:41.823016 3752 authenticatee.cpp:115] Creating new client SASL connection I0915 22:28:41.823370 3754 master.cpp:5089] Authenticating slave(1)@127.0.1.1:54960 I0915 22:28:41.823542 3758 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(3)@127.0.1.1:54960 I0915 22:28:41.823711 3752 authenticator.cpp:92] Creating new server SASL connection I0915 22:28:41.823891 3756 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 I0915 22:28:41.823927 3756 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' I0915 22:28:41.824025 3758 authenticator.cpp:197] Received SASL authentication start I0915 22:28:41.824177 3758 authenticator.cpp:319] Authentication requires more steps I0915 22:28:41.824311 3758 authenticatee.cpp:252] Received SASL authentication step I0915 22:28:41.824445 3758 authenticator.cpp:225] Received SASL authentication step I0915 22:28:41.824507 3758 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0915 22:28:41.824544 3758 auxprop.cpp:174] Looking up auxiliary property '*userPassword' I0915 22:28:41.824609 3758 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0915 22:28:41.824658 3758 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0915 22:28:41.824692 3758 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0915 22:28:41.824717 3758 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0915 22:28:41.824753 3758 authenticator.cpp:311] Authentication success I0915 22:28:41.824874 3756 authenticatee.cpp:292] Authentication success I0915 22:28:41.824914 3757 master.cpp:5119] Successfully authenticated principal 'test-principal' at slave(1)@127.0.1.1:54960 I0915 22:28:41.825027 3759 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(3)@127.0.1.1:54960 I0915 22:28:41.825168 3758 slave.cpp:823] Successfully authenticated with master master@127.0.1.1:54960 I0915 22:28:41.825443 3758 slave.cpp:1217] Will retry registration in 13.419746ms if necessary I0915 22:28:41.825734 3752 master.cpp:3976] Re-registering slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) W0915 22:28:41.826159 3752 master.cpp:5186] Task 1 of framework 20150915-222840-16842879-54960-3733-0000 unknown to the slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) during re-registration: reconciling with the slave W0915 22:28:41.826668 3752 master.cpp:5268] Executor default of framework 20150915-222840-16842879-54960-3733-0000 possibly unknown to the slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) I0915 22:28:41.826745 3756 slave.cpp:967] Re-registered with master master@127.0.1.1:54960 I0915 22:28:41.826797 3752 master.cpp:6118] Removing executor 'default' with resources of framework 20150915-222840-16842879-54960-3733-0000 on slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) I0915 22:28:41.826820 3757 status_update_manager.cpp:183] Resuming sending status updates I0915 22:28:41.826843 3756 slave.cpp:1003] Forwarding total oversubscribed resources W0915 22:28:41.827033 3756 slave.cpp:1043] Slave reconciling task 1 of framework 20150915-222840-16842879-54960-3733-0000 in state TASK_LOST: task unknown to the slave I0915 22:28:41.827244 3752 master.cpp:4164] Sending updated checkpointed resources to slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) I0915 22:28:41.827461 3752 master.cpp:4226] Received update of slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) with total oversubscribed resources I0915 22:28:41.827873 3757 hierarchical.hpp:672] Slave 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) I0915 22:28:41.828115 3757 hierarchical.hpp:1147] No resources available to allocate! I0915 22:28:41.828151 3757 hierarchical.hpp:1230] No inverse offers to send out! I0915 22:28:41.828176 3757 hierarchical.hpp:1065] Performed allocation for slave 20150915-222840-16842879-54960-3733-S0 in 260424ns I0915 22:28:41.828800 3752 status_update_manager.cpp:322] Received status update TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.828882 3752 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.829025 3756 slave.cpp:2235] Updated checkpointed resources from to I0915 22:28:41.829366 3752 status_update_manager.cpp:376] Forwarding update TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 to the slave I0915 22:28:41.829633 3755 slave.cpp:2983] Forwarding the update TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 to master@127.0.1.1:54960 I0915 22:28:41.829941 3755 slave.cpp:2907] Status update manager successfully handled status update TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.830066 3758 master.cpp:4366] Status update TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 from slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) I0915 22:28:41.830114 3758 master.cpp:4405] Forwarding status update TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.830272 3758 master.cpp:6021] Updating the latest state of task 1 of framework 20150915-222840-16842879-54960-3733-0000 to TASK_LOST I0915 22:28:41.830363 3759 sched.cpp:918] Scheduler::statusUpdate took 54887ns I0915 22:28:41.830675 3757 hierarchical.hpp:954] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 20150915-222840-16842879-54960-3733-S0 from framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.835749 3753 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 106.276892ms I0915 22:28:41.835824 3753 replica.cpp:679] Persisted action at 4 I0915 22:28:41.836457 3753 replica.cpp:658] Replica received learned notice for position 4 I0915 22:28:41.836736 3758 master.cpp:6089] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150915-222840-16842879-54960-3733-0000 on slave 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) I0915 22:28:41.836931 3758 master.cpp:3560] Processing ACKNOWLEDGE call 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df for task 1 of framework 20150915-222840-16842879-54960-3733-0000 (default) at scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 on slave 20150915-222840-16842879-54960-3733-S0 I0915 22:28:41.837369 3758 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.837505 3758 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.837813 3758 slave.cpp:2306] Status update manager successfully handled status update acknowledgement (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework 20150915-222840-16842879-54960-3733-0000 E0915 22:28:41.837849 3758 slave.cpp:2317] Status update acknowledgement (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of unknown framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.877821 3753 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 41.327821ms I0915 22:28:41.877909 3753 leveldb.cpp:401] Deleting ~2 keys from leveldb took 47279ns I0915 22:28:41.877940 3753 replica.cpp:679] Persisted action at 4 I0915 22:28:41.877981 3753 replica.cpp:664] Replica learned TRUNCATE action at position 4 I0915 22:28:41.906275 3754 process.cpp:3021] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' I0915 22:28:41.918052 3733 sched.cpp:1754] Asked to stop the driver I0915 22:28:41.918167 3754 sched.cpp:1040] Stopping framework '20150915-222840-16842879-54960-3733-0000' I0915 22:28:41.918184 3752 master.cpp:921] Master terminating I0915 22:28:41.918462 3755 hierarchical.hpp:643] Removed slave 20150915-222840-16842879-54960-3733-S0 I0915 22:28:41.918792 3755 hierarchical.hpp:490] Removed framework 20150915-222840-16842879-54960-3733-0000 I0915 22:28:41.919427 3756 slave.cpp:3151] master@127.0.1.1:54960 exited W0915 22:28:41.919839 3756 slave.cpp:3154] Master disconnected! Waiting for a new master to be elected I0915 22:28:41.923146 3753 slave.cpp:572] Slave terminating [ OK ] MasterSlaveReconciliationTest.ReconcileLostTask (1443 ms) [----------] 1 test from MasterSlaveReconciliationTest (1443 ms total) [----------] Global test environment tear-down [==========] 1 test from 1 test case ran. (1780 ms total) [ PASSED ] 1 test. make[3]: Leaving directory `/home/gyliu/src/mesos/bug-fix/mesos/build/src' make[2]: Leaving directory `/home/gyliu/src/mesos/bug-fix/mesos/build/src' make[1]: Leaving directory `/home/gyliu/src/mesos/bug-fix/mesos/build/src' gyliu@devstack007: was: Observed this on internal CI {code} DEBUG: [----------] 5 tests from MasterSlaveReconciliationTest DEBUG: [ RUN ] MasterSlaveReconciliationTest.SlaveReregisterTerminatedExecutor DEBUG: Using temporary directory '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_QJPUzf' DEBUG: [ OK ] MasterSlaveReconciliationTest.SlaveReregisterTerminatedExecutor (78 ms) DEBUG: [ RUN ] MasterSlaveReconciliationTest.ReconcileLostTask DEBUG: Using temporary directory '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_16KDgE' DEBUG: tests/master_slave_reconciliation_tests.cpp:226: Failure DEBUG: Failed to wait 15secs for statusUpdateMessage DEBUG: tests/master_slave_reconciliation_tests.cpp:216: Failure DEBUG: Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))... DEBUG: Expected: to be called once DEBUG: Actual: never called - unsatisfied and active DEBUG: I0914 08:51:27.825984 16062 leveldb.cpp:438] Reading position from leveldb took 16151ns DEBUG: I0914 08:51:27.828069 16049 registrar.cpp:342] Successfully fetched the registry (0B) in 7648us DEBUG: I0914 08:51:27.828119 16049 registrar.cpp:441] Applied 1 operations in 2805ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.829991 16066 log.cpp:685] Attempting to append 222 bytes to the log DEBUG: I0914 08:51:27.830029 16066 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1 DEBUG: I0914 08:51:27.830729 16053 replica.cpp:511] Replica received write request for position 1 DEBUG: I0914 08:51:27.831167 16053 leveldb.cpp:343] Persisting action (241 bytes) to leveldb took 414748ns DEBUG: I0914 08:51:27.831185 16053 replica.cpp:679] Persisted action at 1 DEBUG: I0914 08:51:27.831493 16058 replica.cpp:658] Replica received learned notice for position 1 DEBUG: I0914 08:51:27.831698 16058 leveldb.cpp:343] Persisting action (243 bytes) to leveldb took 185223ns DEBUG: I0914 08:51:27.831714 16058 replica.cpp:679] Persisted action at 1 DEBUG: I0914 08:51:27.831722 16058 replica.cpp:664] Replica learned APPEND action at position 1 DEBUG: I0914 08:51:27.831989 16056 registrar.cpp:486] Successfully updated the 'registry' in 3.827968ms DEBUG: I0914 08:51:27.832041 16052 log.cpp:704] Attempting to truncate the log to 1 DEBUG: I0914 08:51:27.832093 16056 registrar.cpp:372] Successfully recovered registrar DEBUG: I0914 08:51:27.832259 16072 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2 DEBUG: I0914 08:51:27.832259 16062 master.cpp:1404] Recovered 0 slaves from the Registry (183B) ; allowing 10mins for slaves to re-register DEBUG: I0914 08:51:27.832882 16060 replica.cpp:511] Replica received write request for position 2 DEBUG: I0914 08:51:27.833243 16060 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 340843ns DEBUG: I0914 08:51:27.833261 16060 replica.cpp:679] Persisted action at 2 DEBUG: I0914 08:51:27.833593 16050 replica.cpp:658] Replica received learned notice for position 2 DEBUG: I0914 08:51:27.833724 16050 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 112560ns DEBUG: I0914 08:51:27.833755 16050 leveldb.cpp:401] Deleting ~1 keys from leveldb took 16580ns DEBUG: I0914 08:51:27.833765 16050 replica.cpp:679] Persisted action at 2 DEBUG: I0914 08:51:27.833775 16050 replica.cpp:664] Replica learned TRUNCATE action at position 2 DEBUG: I0914 08:51:27.843340 16057 http.cpp:333] HTTP POST for /master/maintenance/schedule from 172.18.4.102:46471 DEBUG: I0914 08:51:27.843801 16050 registrar.cpp:441] Applied 1 operations in 25197ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.845721 16068 log.cpp:685] Attempting to append 328 bytes to the log DEBUG: I0914 08:51:27.845772 16068 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3 DEBUG: I0914 08:51:27.846606 16052 replica.cpp:511] Replica received write request for position 3 DEBUG: I0914 08:51:27.847012 16052 leveldb.cpp:343] Persisting action (347 bytes) to leveldb took 387519ns DEBUG: I0914 08:51:27.847026 16052 replica.cpp:679] Persisted action at 3 DEBUG: I0914 08:51:27.847698 16048 replica.cpp:658] Replica received learned notice for position 3 DEBUG: I0914 08:51:27.848108 16048 leveldb.cpp:343] Persisting action (349 bytes) to leveldb took 375264ns DEBUG: I0914 08:51:27.848125 16048 replica.cpp:679] Persisted action at 3 DEBUG: I0914 08:51:27.848137 16048 replica.cpp:664] Replica learned APPEND action at position 3 DEBUG: I0914 08:51:27.848461 16048 registrar.cpp:486] Successfully updated the 'registry' in 4.636928ms DEBUG: I0914 08:51:27.848829 16049 log.cpp:704] Attempting to truncate the log to 3 DEBUG: I0914 08:51:27.849287 16048 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4 DEBUG: I0914 08:51:27.850116 16066 http.cpp:333] HTTP GET for /master/maintenance/status from 172.18.4.102:46472 DEBUG: I0914 08:51:27.850126 16051 replica.cpp:511] Replica received write request for position 4 DEBUG: I0914 08:51:27.850512 16051 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 364892ns DEBUG: I0914 08:51:27.850528 16051 replica.cpp:679] Persisted action at 4 DEBUG: I0914 08:51:27.851152 16067 http.cpp:333] HTTP POST for /master/machine/down from 172.18.4.102:46473 DEBUG: I0914 08:51:27.851207 16050 replica.cpp:658] Replica received learned notice for position 4 DEBUG: I0914 08:51:27.851302 16075 registrar.cpp:441] Applied 1 operations in 13246ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.851485 16050 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 258177ns DEBUG: I0914 08:51:27.851516 16050 leveldb.cpp:401] Deleting ~2 keys from leveldb took 15870ns DEBUG: I0914 08:51:27.851526 16050 replica.cpp:679] Persisted action at 4 DEBUG: I0914 08:51:27.851532 16050 replica.cpp:664] Replica learned TRUNCATE action at position 4 DEBUG: I0914 08:51:27.853145 16066 log.cpp:685] Attempting to append 328 bytes to the log DEBUG: I0914 08:51:27.853214 16051 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 5 DEBUG: I0914 08:51:27.853755 16066 replica.cpp:511] Replica received write request for position 5 DEBUG: I0914 08:51:27.853879 16066 leveldb.cpp:343] Persisting action (347 bytes) to leveldb took 106193ns DEBUG: I0914 08:51:27.853893 16066 replica.cpp:679] Persisted action at 5 DEBUG: I0914 08:51:27.854228 16066 replica.cpp:658] Replica received learned notice for position 5 DEBUG: I0914 08:51:27.854496 16066 leveldb.cpp:343] Persisting action (349 bytes) to leveldb took 252636ns DEBUG: I0914 08:51:27.854508 16066 replica.cpp:679] Persisted action at 5 DEBUG: I0914 08:51:27.854514 16066 replica.cpp:664] Replica learned APPEND action at position 5 DEBUG: I0914 08:51:27.854825 16075 registrar.cpp:486] Successfully updated the 'registry' in 3.490816ms DEBUG: I0914 08:51:27.854883 16060 log.cpp:704] Attempting to truncate the log to 5 DEBUG: I0914 08:51:27.854934 16055 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 6 DEBUG: I0914 08:51:27.855425 16067 replica.cpp:511] Replica received write request for position 6 DEBUG: I0914 08:51:27.855696 16067 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 251165ns DEBUG: I0914 08:51:27.855711 16067 replica.cpp:679] Persisted action at 6 DEBUG: I0914 08:51:27.856086 16053 replica.cpp:658] Replica received learned notice for position 6 DEBUG: I0914 08:51:27.856302 16075 http.cpp:333] HTTP GET for /master/maintenance/status from 172.18.4.102:46474 DEBUG: I0914 08:51:27.856345 16053 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 238357ns DEBUG: I0914 08:51:27.856377 16053 leveldb.cpp:401] Deleting ~2 keys from leveldb took 14882ns DEBUG: I0914 08:51:27.856391 16053 replica.cpp:679] Persisted action at 6 DEBUG: I0914 08:51:27.856407 16053 replica.cpp:664] Replica learned TRUNCATE action at position 6 DEBUG: I0914 08:51:27.857182 16056 http.cpp:333] HTTP POST for /master/machine/up from 172.18.4.102:46475 DEBUG: I0914 08:51:27.857316 16048 registrar.cpp:441] Applied 1 operations in 14168ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.859238 16048 log.cpp:685] Attempting to append 284 bytes to the log DEBUG: I0914 08:51:27.859295 16068 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 7 DEBUG: I0914 08:51:27.860258 16056 replica.cpp:511] Replica received write request for position 7 DEBUG: I0914 08:51:27.860399 16056 leveldb.cpp:343] Persisting action (303 bytes) to leveldb took 119965ns DEBUG: I0914 08:51:27.860414 16056 replica.cpp:679] Persisted action at 7 DEBUG: I0914 08:51:27.860749 16063 replica.cpp:658] Replica received learned notice for position 7 DEBUG: I0914 08:51:27.861124 16063 leveldb.cpp:343] Persisting action (305 bytes) to leveldb took 357862ns DEBUG: I0914 08:51:27.861142 16063 replica.cpp:679] Persisted action at 7 DEBUG: I0914 08:51:27.861155 16063 replica.cpp:664] Replica learned APPEND action at position 7 DEBUG: I0914 08:51:27.861444 16066 registrar.cpp:486] Successfully updated the 'registry' in 4.096768ms DEBUG: I0914 08:51:27.861593 16059 log.cpp:704] Attempting to truncate the log to 7 DEBUG: I0914 08:51:27.861699 16069 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 8 DEBUG: I0914 08:51:27.862619 16075 replica.cpp:511] Replica received write request for position 8 DEBUG: I0914 08:51:27.862737 16072 http.cpp:333] HTTP GET for /master/maintenance/status from 172.18.4.102:46476 DEBUG: I0914 08:51:27.862931 16075 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 291315ns DEBUG: I0914 08:51:27.862946 16075 replica.cpp:679] Persisted action at 8 DEBUG: I0914 08:51:27.863574 16068 master.cpp:919] Master terminating DEBUG: I0914 08:51:27.863574 16052 replica.cpp:658] Replica received learned notice for position 8 DEBUG: I0914 08:51:27.863929 16052 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 320008ns DEBUG: I0914 08:51:27.863972 16052 leveldb.cpp:401] Deleting ~2 keys from leveldb took 25476ns DEBUG: I0914 08:51:27.863988 16052 replica.cpp:679] Persisted action at 8 DEBUG: I0914 08:51:27.863998 16052 replica.cpp:664] Replica learned TRUNCATE action at position 8 DEBUG: I0914 08:51:27.867812 16033 leveldb.cpp:176] Opened db in 1.853028ms DEBUG: I0914 08:51:27.868635 16033 leveldb.cpp:183] Compacted db in 800863ns DEBUG: I0914 08:51:27.868665 16033 leveldb.cpp:198] Created db iterator in 12920ns DEBUG: I0914 08:51:27.868680 16033 leveldb.cpp:204] Seeked to beginning of db in 739ns DEBUG: I0914 08:51:27.868688 16033 leveldb.cpp:273] Iterated through 0 keys in the db in 360ns DEBUG: I0914 08:51:27.868702 16033 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned DEBUG: I0914 08:51:27.869283 16066 recover.cpp:449] Starting replica recovery DEBUG: I0914 08:51:27.869727 16075 recover.cpp:475] Replica is in EMPTY status DEBUG: I0914 08:51:27.870440 16051 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request DEBUG: I0914 08:51:27.870543 16048 master.cpp:379] Master 20150914-085127-1711542956-33300-16033 (atlc-bev-05-sr1.corpdc.twttr.net) started on 172.18.4.102:33300 DEBUG: I0914 08:51:27.870556 16048 master.cpp:381] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_QJPUzf/credentials" --framework_sorter="drf" --help="false" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_QJPUzf/master" --zk_session_timeout="10secs" DEBUG: I0914 08:51:27.870694 16048 master.cpp:426] Master only allowing authenticated frameworks to register DEBUG: I0914 08:51:27.870702 16048 master.cpp:431] Master only allowing authenticated slaves to register DEBUG: I0914 08:51:27.870708 16048 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_QJPUzf/credentials' DEBUG: I0914 08:51:27.870971 16057 recover.cpp:195] Received a recover response from a replica in EMPTY status DEBUG: I0914 08:51:27.870975 16048 master.cpp:470] Using default 'crammd5' authenticator DEBUG: I0914 08:51:27.871291 16048 master.cpp:507] Authorization enabled DEBUG: I0914 08:51:27.871600 16061 recover.cpp:566] Updating replica status to STARTING DEBUG: I0914 08:51:27.871906 16069 master.cpp:1594] The newly elected leader is master@172.18.4.102:33300 with id 20150914-085127-1711542956-33300-16033 DEBUG: I0914 08:51:27.871924 16069 master.cpp:1607] Elected as the leading master! DEBUG: I0914 08:51:27.871934 16069 master.cpp:1367] Recovering from registrar DEBUG: I0914 08:51:27.872216 16051 registrar.cpp:309] Recovering registrar DEBUG: I0914 08:51:27.872303 16068 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 492212ns DEBUG: I0914 08:51:27.872318 16068 replica.cpp:323] Persisted replica status to STARTING DEBUG: I0914 08:51:27.872514 16058 recover.cpp:475] Replica is in STARTING status DEBUG: I0914 08:51:27.872936 16055 replica.cpp:641] Replica in STARTING status received a broadcasted recover request DEBUG: I0914 08:51:27.873101 16065 recover.cpp:195] Received a recover response from a replica in STARTING status DEBUG: I0914 08:51:27.873291 16053 recover.cpp:566] Updating replica status to VOTING DEBUG: I0914 08:51:27.873723 16064 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 257045ns DEBUG: I0914 08:51:27.873740 16064 replica.cpp:323] Persisted replica status to VOTING DEBUG: I0914 08:51:27.873780 16064 recover.cpp:580] Successfully joined the Paxos group DEBUG: I0914 08:51:27.873828 16064 recover.cpp:464] Recover process terminated DEBUG: I0914 08:51:27.874064 16065 log.cpp:661] Attempting to start the writer DEBUG: I0914 08:51:27.874729 16055 replica.cpp:477] Replica received implicit promise request with proposal 1 DEBUG: I0914 08:51:27.875007 16055 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 255863ns DEBUG: I0914 08:51:27.875025 16055 replica.cpp:345] Persisted promised to 1 DEBUG: I0914 08:51:27.875612 16054 coordinator.cpp:231] Coordinator attemping to fill missing position DEBUG: I0914 08:51:27.876494 16061 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2 DEBUG: I0914 08:51:27.876749 16061 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 235812ns DEBUG: I0914 08:51:27.876762 16061 replica.cpp:679] Persisted action at 0 DEBUG: I0914 08:51:27.877432 16051 replica.cpp:511] Replica received write request for position 0 DEBUG: I0914 08:51:27.877468 16051 leveldb.cpp:438] Reading position from leveldb took 15906ns DEBUG: I0914 08:51:27.877743 16051 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 257870ns DEBUG: I0914 08:51:27.877758 16051 replica.cpp:679] Persisted action at 0 DEBUG: I0914 08:51:27.878149 16060 replica.cpp:658] Replica received learned notice for position 0 DEBUG: I0914 08:51:27.878453 16060 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 284861ns DEBUG: I0914 08:51:27.878468 16060 replica.cpp:679] Persisted action at 0 DEBUG: I0914 08:51:27.878474 16060 replica.cpp:664] Replica learned NOP action at position 0 DEBUG: I0914 08:51:27.878774 16068 log.cpp:677] Writer started with ending position 0 DEBUG: I0914 08:51:27.879273 16069 leveldb.cpp:438] Reading position from leveldb took 12185ns DEBUG: I0914 08:51:27.881232 16054 registrar.cpp:342] Successfully fetched the registry (0B) in 8.990976ms DEBUG: I0914 08:51:27.881278 16054 registrar.cpp:441] Applied 1 operations in 3223ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.883201 16051 log.cpp:685] Attempting to append 222 bytes to the log DEBUG: I0914 08:51:27.883260 16051 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1 DEBUG: I0914 08:51:27.883821 16068 replica.cpp:511] Replica received write request for position 1 DEBUG: I0914 08:51:27.884290 16068 leveldb.cpp:343] Persisting action (241 bytes) to leveldb took 448700ns DEBUG: I0914 08:51:27.884310 16068 replica.cpp:679] Persisted action at 1 DEBUG: I0914 08:51:27.884593 16048 replica.cpp:658] Replica received learned notice for position 1 DEBUG: I0914 08:51:27.884830 16048 leveldb.cpp:343] Persisting action (243 bytes) to leveldb took 220295ns DEBUG: I0914 08:51:27.884850 16048 replica.cpp:679] Persisted action at 1 DEBUG: I0914 08:51:27.884858 16048 replica.cpp:664] Replica learned APPEND action at position 1 DEBUG: I0914 08:51:27.885392 16067 registrar.cpp:486] Successfully updated the 'registry' in 4.092928ms DEBUG: I0914 08:51:27.885406 16053 log.cpp:704] Attempting to truncate the log to 1 DEBUG: I0914 08:51:27.885455 16067 registrar.cpp:372] Successfully recovered registrar DEBUG: I0914 08:51:27.885723 16065 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2 DEBUG: I0914 08:51:27.885819 16050 master.cpp:1404] Recovered 0 slaves from the Registry (183B) ; allowing 10mins for slaves to re-register DEBUG: I0914 08:51:27.886951 16060 replica.cpp:511] Replica received write request for position 2 DEBUG: I0914 08:51:27.887383 16060 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 412535ns DEBUG: I0914 08:51:27.887398 16060 replica.cpp:679] Persisted action at 2 DEBUG: I0914 08:51:27.887675 16060 replica.cpp:658] Replica received learned notice for position 2 DEBUG: I0914 08:51:27.887959 16060 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 268535ns DEBUG: I0914 08:51:27.887984 16060 leveldb.cpp:401] Deleting ~1 keys from leveldb took 11823ns DEBUG: I0914 08:51:27.887992 16060 replica.cpp:679] Persisted action at 2 DEBUG: I0914 08:51:27.888000 16060 replica.cpp:664] Replica learned TRUNCATE action at position 2 DEBUG: I0914 08:51:27.900251 16075 slave.cpp:190] Slave started on 97)@172.18.4.102:33300 DEBUG: I0914 08:51:27.900267 16075 slave.cpp:191] Flags at startup: --appc_provisioner_backend="copy" --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/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --egress_unique_flow_per_container="false" --enforce_container_disk_quota="false" --ephemeral_ports_per_container="1024" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/builddir/build/BUILD/mesos-0.25.0/src" --logbufsecs="0" --logging_level="INFO" --network_enable_socket_statistics_details="false" --network_enable_socket_statistics_summary="false" --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" --resource_monitoring_interval="1secs" --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" --version="false" --work_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk" DEBUG: I0914 08:51:27.900552 16075 credentials.hpp:85] Loading credential for authentication from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/credential' DEBUG: I0914 08:51:27.900641 16075 slave.cpp:321] Slave using credential for: test-principal DEBUG: I0914 08:51:27.900789 16075 slave.cpp:354] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] DEBUG: I0914 08:51:27.901268 16075 slave.cpp:384] Slave hostname: atlc-bev-05-sr1.corpdc.twttr.net DEBUG: I0914 08:51:27.901293 16075 slave.cpp:389] Slave checkpoint: true DEBUG: I0914 08:51:27.901612 16052 state.cpp:54] Recovering state from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/meta' DEBUG: I0914 08:51:27.901886 16051 status_update_manager.cpp:202] Recovering status update manager DEBUG: I0914 08:51:27.901988 16051 slave.cpp:4077] Finished recovery DEBUG: I0914 08:51:27.902938 16061 status_update_manager.cpp:176] Pausing sending status updates DEBUG: I0914 08:51:27.903105 16051 slave.cpp:692] New master detected at master@172.18.4.102:33300 DEBUG: I0914 08:51:27.903131 16051 slave.cpp:755] Authenticating with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.903142 16051 slave.cpp:760] Using default CRAM-MD5 authenticatee DEBUG: I0914 08:51:27.903192 16051 slave.cpp:728] Detecting new master DEBUG: I0914 08:51:27.903234 16075 authenticatee.cpp:115] Creating new client SASL connection DEBUG: I0914 08:51:27.903472 16053 master.cpp:4763] Authenticating slave(97)@172.18.4.102:33300 DEBUG: I0914 08:51:27.903692 16064 authenticator.cpp:92] Creating new server SASL connection DEBUG: I0914 08:51:27.903785 16068 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 DEBUG: I0914 08:51:27.903810 16068 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' DEBUG: I0914 08:51:27.903872 16053 authenticator.cpp:197] Received SASL authentication start DEBUG: I0914 08:51:27.903930 16053 authenticator.cpp:319] Authentication requires more steps DEBUG: I0914 08:51:27.903970 16053 authenticatee.cpp:252] Received SASL authentication step DEBUG: I0914 08:51:27.904026 16053 authenticator.cpp:225] Received SASL authentication step DEBUG: I0914 08:51:27.904062 16053 authenticator.cpp:311] Authentication success DEBUG: I0914 08:51:27.904171 16050 authenticatee.cpp:292] Authentication success DEBUG: I0914 08:51:27.904202 16067 master.cpp:4793] Successfully authenticated principal 'test-principal' at slave(97)@172.18.4.102:33300 DEBUG: I0914 08:51:27.904386 16060 slave.cpp:823] Successfully authenticated with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.904501 16057 master.cpp:3705] Registering slave at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with id 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.904618 16059 registrar.cpp:441] Applied 1 operations in 14863ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.907174 16053 log.cpp:685] Attempting to append 413 bytes to the log DEBUG: I0914 08:51:27.907318 16072 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3 DEBUG: I0914 08:51:27.907380 16033 sched.cpp:164] Version: 0.25.0-rc0 DEBUG: I0914 08:51:27.907639 16051 sched.cpp:262] New master detected at master@172.18.4.102:33300 DEBUG: I0914 08:51:27.907763 16048 replica.cpp:511] Replica received write request for position 3 DEBUG: I0914 08:51:27.907821 16051 sched.cpp:318] Authenticating with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.907837 16051 sched.cpp:325] Using default CRAM-MD5 authenticatee DEBUG: I0914 08:51:27.907939 16048 leveldb.cpp:343] Persisting action (432 bytes) to leveldb took 155708ns DEBUG: I0914 08:51:27.907955 16048 replica.cpp:679] Persisted action at 3 DEBUG: I0914 08:51:27.908052 16048 authenticatee.cpp:115] Creating new client SASL connection DEBUG: I0914 08:51:27.908280 16060 master.cpp:4763] Authenticating scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 DEBUG: I0914 08:51:27.908388 16066 replica.cpp:658] Replica received learned notice for position 3 DEBUG: I0914 08:51:27.908474 16068 authenticator.cpp:92] Creating new server SASL connection DEBUG: I0914 08:51:27.908563 16062 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 DEBUG: I0914 08:51:27.908588 16062 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' DEBUG: I0914 08:51:27.908646 16064 authenticator.cpp:197] Received SASL authentication start DEBUG: I0914 08:51:27.908707 16064 authenticator.cpp:319] Authentication requires more steps DEBUG: I0914 08:51:27.908753 16064 authenticatee.cpp:252] Received SASL authentication step DEBUG: I0914 08:51:27.908782 16066 leveldb.cpp:343] Persisting action (434 bytes) to leveldb took 376798ns DEBUG: I0914 08:51:27.908799 16066 replica.cpp:679] Persisted action at 3 DEBUG: I0914 08:51:27.908812 16066 replica.cpp:664] Replica learned APPEND action at position 3 DEBUG: I0914 08:51:27.908814 16068 authenticator.cpp:225] Received SASL authentication step DEBUG: I0914 08:51:27.908859 16068 authenticator.cpp:311] Authentication success DEBUG: I0914 08:51:27.908977 16058 authenticatee.cpp:292] Authentication success DEBUG: I0914 08:51:27.909011 16072 master.cpp:4793] Successfully authenticated principal 'test-principal' at scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 DEBUG: I0914 08:51:27.909116 16055 sched.cpp:407] Successfully authenticated with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.909315 16048 master.cpp:2163] Received SUBSCRIBE call for framework 'default' at scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 DEBUG: I0914 08:51:27.909342 16048 master.cpp:1633] Authorizing framework principal 'test-principal' to receive offers for role '*' DEBUG: I0914 08:51:27.909376 16060 registrar.cpp:486] Successfully updated the 'registry' in 4.742144ms DEBUG: I0914 08:51:27.909507 16075 log.cpp:704] Attempting to truncate the log to 3 DEBUG: I0914 08:51:27.909586 16068 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4 DEBUG: I0914 08:51:27.909894 16048 hierarchical.hpp:543] Added slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) DEBUG: I0914 08:51:27.909901 16062 master.cpp:3768] Registered slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] DEBUG: I0914 08:51:27.909935 16059 slave.cpp:867] Registered with master master@172.18.4.102:33300; given slave ID 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.909989 16062 master.cpp:2233] Subscribing framework default with checkpointing disabled and capabilities [ ] DEBUG: I0914 08:51:27.910037 16066 replica.cpp:511] Replica received write request for position 4 DEBUG: I0914 08:51:27.910058 16054 status_update_manager.cpp:183] Resuming sending status updates DEBUG: I0914 08:51:27.910128 16064 hierarchical.hpp:392] Added framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.910307 16062 master.cpp:3675] Slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) already registered, resending acknowledgement DEBUG: I0914 08:51:27.910397 16066 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 338570ns DEBUG: I0914 08:51:27.910403 16068 sched.cpp:640] Framework registered with 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.910411 16066 replica.cpp:679] Persisted action at 4 DEBUG: I0914 08:51:27.910456 16062 master.cpp:4682] Sending 1 offers to framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 DEBUG: I0914 08:51:27.910575 16059 slave.cpp:926] Forwarding total oversubscribed resources DEBUG: I0914 08:51:27.910720 16048 master.cpp:4067] Received update of slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with total oversubscribed resources DEBUG: W0914 08:51:27.910739 16059 slave.cpp:912] Already registered with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.910751 16059 slave.cpp:926] Forwarding total oversubscribed resources DEBUG: I0914 08:51:27.910804 16067 master.cpp:4067] Received update of slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with total oversubscribed resources DEBUG: I0914 08:51:27.910801 16048 hierarchical.hpp:603] Slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) DEBUG: I0914 08:51:27.910823 16069 replica.cpp:658] Replica received learned notice for position 4 DEBUG: I0914 08:51:27.910900 16048 hierarchical.hpp:603] Slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) DEBUG: I0914 08:51:27.911149 16069 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 305721ns DEBUG: I0914 08:51:27.911177 16069 leveldb.cpp:401] Deleting ~2 keys from leveldb took 14592ns DEBUG: I0914 08:51:27.911186 16069 replica.cpp:679] Persisted action at 4 DEBUG: I0914 08:51:27.911193 16069 replica.cpp:664] Replica learned TRUNCATE action at position 4 DEBUG: I0914 08:51:27.911244 16068 master.cpp:2808] Processing ACCEPT call for offers: [ 20150914-085127-1711542956-33300-16033-O0 ] on slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) for framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 DEBUG: I0914 08:51:27.911264 16068 master.cpp:2639] Authorizing framework principal 'test-principal' to launch task 0 as user 'mockbuild' DEBUG: W0914 08:51:27.911692 16052 validation.cpp:419] 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. DEBUG: W0914 08:51:27.911718 16052 validation.cpp:431] 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. DEBUG: I0914 08:51:27.911770 16052 master.hpp:173] Adding task 0 with resources cpus(*):1; mem(*):512 on slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.911794 16052 master.cpp:3138] Launching task 0 of framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 with resources cpus(*):1; mem(*):512 on slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.912042 16057 slave.cpp:1257] Got assigned task 0 for framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.912041 16075 hierarchical.hpp:816] Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):512) on slave 20150914-085127-1711542956-33300-16033-S0 from framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.912197 16057 slave.cpp:1373] Launching task 0 for framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.922344 16057 slave.cpp:4807] Launching executor default of framework 20150914-085127-1711542956-33300-16033-0000 with resources in work directory '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/slaves/20150914-085127-1711542956-33300-16033-S0/frameworks/20150914-085127-1711542956-33300-16033-0000/executors/default/runs/1790de07-f21d-46f4-a72a-aa1de229e794' DEBUG: I0914 08:51:27.924831 16057 exec.cpp:134] Version: 0.25.0-rc0 DEBUG: I0914 08:51:27.925010 16057 slave.cpp:1591] Queuing task '0' for executor default of framework '20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.925071 16057 slave.cpp:2366] Got registration for executor 'default' of framework 20150914-085127-1711542956-33300-16033-0000 from executor(45)@172.18.4.102:33300 DEBUG: I0914 08:51:27.925195 16054 exec.cpp:208] Executor registered on slave 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.925218 16057 slave.cpp:1747] Sending queued task '0' to executor 'default' of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.928778 16054 slave.cpp:2704] Handling status update TASK_RUNNING (UUID: 07b06bae-052c-41f5-9e37-9151d4d7b462) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 from executor(45)@172.18.4.102:33300 DEBUG: I0914 08:51:27.928860 16054 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 07b06bae-052c-41f5-9e37-9151d4d7b462) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.929061 16048 slave.cpp:2983] Forwarding the update TASK_RUNNING (UUID: 07b06bae-052c-41f5-9e37-9151d4d7b462) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 to master@172.18.4.102:33300 DEBUG: I0914 08:51:27.929122 16048 slave.cpp:2913] Sending acknowledgement for status update TASK_RUNNING (UUID: 07b06bae-052c-41f5-9e37-9151d4d7b462) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 to executor(45)@172.18.4.102:33300 DEBUG: I0914 08:51:27.929515 16072 master.cpp:4138] Status update TASK_RUNNING (UUID: 07b06bae-052c-41f5-9e37-9151d4d7b462) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 from slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.929572 16072 master.cpp:4177] Forwarding status update TASK_RUNNING (UUID: 07b06bae-052c-41f5-9e37-9151d4d7b462) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.929756 16072 master.cpp:5645] Updating the latest state of task 0 of framework 20150914-085127-1711542956-33300-16033-0000 to TASK_RUNNING DEBUG: I0914 08:51:27.930469 16050 master.cpp:3467] Processing ACKNOWLEDGE call 07b06bae-052c-41f5-9e37-9151d4d7b462 for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 on slave 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.930764 16056 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 07b06bae-052c-41f5-9e37-9151d4d7b462) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.933039 16063 slave.cpp:2704] Handling status update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 from executor(45)@172.18.4.102:33300 DEBUG: I0914 08:51:27.933179 16063 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.933315 16075 slave.cpp:2983] Forwarding the update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 to master@172.18.4.102:33300 DEBUG: I0914 08:51:27.933429 16075 slave.cpp:2913] Sending acknowledgement for status update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 to executor(45)@172.18.4.102:33300 DEBUG: I0914 08:51:27.934675 16064 slave.cpp:3407] Executor 'default' of framework 20150914-085127-1711542956-33300-16033-0000 exited with status 0 DEBUG: I0914 08:51:27.934798 16055 master.cpp:4231] Executor default of framework 20150914-085127-1711542956-33300-16033-0000 on slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net): exited with status 0 DEBUG: I0914 08:51:27.934820 16055 master.cpp:5742] Removing executor 'default' with resources of framework 20150914-085127-1711542956-33300-16033-0000 on slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.936911 16069 status_update_manager.cpp:176] Pausing sending status updates DEBUG: I0914 08:51:27.936988 16059 slave.cpp:692] New master detected at master@172.18.4.102:33300 DEBUG: I0914 08:51:27.937008 16059 slave.cpp:755] Authenticating with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.937016 16059 slave.cpp:760] Using default CRAM-MD5 authenticatee DEBUG: I0914 08:51:27.937057 16059 slave.cpp:728] Detecting new master DEBUG: I0914 08:51:27.937085 16059 slave.cpp:1079] Skipping registration because not authenticated DEBUG: I0914 08:51:27.937119 16064 authenticatee.cpp:115] Creating new client SASL connection DEBUG: I0914 08:51:27.937335 16052 master.cpp:4763] Authenticating slave(97)@172.18.4.102:33300 DEBUG: I0914 08:51:27.937449 16072 authenticator.cpp:92] Creating new server SASL connection DEBUG: I0914 08:51:27.937563 16072 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 DEBUG: I0914 08:51:27.937587 16072 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' DEBUG: I0914 08:51:27.938004 16064 authenticator.cpp:197] Received SASL authentication start DEBUG: I0914 08:51:27.938055 16064 authenticator.cpp:319] Authentication requires more steps DEBUG: I0914 08:51:27.938093 16064 authenticatee.cpp:252] Received SASL authentication step DEBUG: I0914 08:51:27.938125 16064 authenticator.cpp:225] Received SASL authentication step DEBUG: I0914 08:51:27.938150 16064 authenticator.cpp:311] Authentication success DEBUG: I0914 08:51:27.938238 16075 authenticatee.cpp:292] Authentication success DEBUG: I0914 08:51:27.938287 16064 master.cpp:4793] Successfully authenticated principal 'test-principal' at slave(97)@172.18.4.102:33300 DEBUG: I0914 08:51:27.938550 16075 slave.cpp:823] Successfully authenticated with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.938859 16067 master.cpp:3842] Re-registering slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.938933 16067 master.cpp:4005] Sending updated checkpointed resources to slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.938944 16075 slave.cpp:967] Re-registered with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.938985 16075 slave.cpp:1003] Forwarding total oversubscribed resources DEBUG: I0914 08:51:27.938992 16067 status_update_manager.cpp:183] Resuming sending status updates DEBUG: W0914 08:51:27.939002 16067 status_update_manager.cpp:190] Resending status update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.939107 16064 master.cpp:4067] Received update of slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with total oversubscribed resources DEBUG: I0914 08:51:27.939177 16064 hierarchical.hpp:603] Slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):512) DEBUG: I0914 08:51:27.939244 16075 slave.cpp:2235] Updated checkpointed resources from to DEBUG: I0914 08:51:27.939278 16075 slave.cpp:2983] Forwarding the update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 to master@172.18.4.102:33300 DEBUG: I0914 08:51:27.939524 16056 master.cpp:4138] Status update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 from slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.939548 16056 master.cpp:4177] Forwarding status update TASK_FINISHED (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.939609 16056 master.cpp:5645] Updating the latest state of task 0 of framework 20150914-085127-1711542956-33300-16033-0000 to TASK_FINISHED DEBUG: I0914 08:51:27.939719 16069 hierarchical.hpp:816] Recovered cpus(*):1; mem(*):512 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 20150914-085127-1711542956-33300-16033-S0 from framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.940119 16033 sched.cpp:1746] Asked to stop the driver DEBUG: I0914 08:51:27.940129 16048 master.cpp:5713] Removing task 0 with resources cpus(*):1; mem(*):512 of framework 20150914-085127-1711542956-33300-16033-0000 on slave 20150914-085127-1711542956-33300-16033-S0 at slave(97)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.940165 16055 sched.cpp:1032] Stopping framework '20150914-085127-1711542956-33300-16033-0000' DEBUG: I0914 08:51:27.940173 16048 master.cpp:3467] Processing ACKNOWLEDGE call 2e8169d3-0ec3-44ee-a45e-4813412a8415 for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-86c78094-ed28-4b3c-91ff-5692d7646081@172.18.4.102:33300 on slave 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.940207 16048 master.cpp:919] Master terminating DEBUG: I0914 08:51:27.940387 16066 hierarchical.hpp:574] Removed slave 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.940412 16058 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 2e8169d3-0ec3-44ee-a45e-4813412a8415) for task 0 of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.940423 16066 hierarchical.hpp:429] Removed framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.940558 16052 slave.cpp:3511] Cleaning up executor 'default' of framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.940670 16052 slave.cpp:3600] Cleaning up framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.940685 16063 gc.cpp:56] Scheduling '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/slaves/20150914-085127-1711542956-33300-16033-S0/frameworks/20150914-085127-1711542956-33300-16033-0000/executors/default/runs/1790de07-f21d-46f4-a72a-aa1de229e794' for gc 6.99998911326519days in the future DEBUG: I0914 08:51:27.940729 16063 gc.cpp:56] Scheduling '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/slaves/20150914-085127-1711542956-33300-16033-S0/frameworks/20150914-085127-1711542956-33300-16033-0000/executors/default' for gc 6.99998911282667days in the future DEBUG: I0914 08:51:27.940739 16064 status_update_manager.cpp:284] Closing status update streams for framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.940747 16052 slave.cpp:3151] master@172.18.4.102:33300 exited DEBUG: W0914 08:51:27.940763 16052 slave.cpp:3154] Master disconnected! Waiting for a new master to be elected DEBUG: I0914 08:51:27.940759 16063 gc.cpp:56] Scheduling '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminatedExecutor_JwLRsk/slaves/20150914-085127-1711542956-33300-16033-S0/frameworks/20150914-085127-1711542956-33300-16033-0000' for gc 6.99998911199111days in the future DEBUG: I0914 08:51:27.942140 16033 slave.cpp:572] Slave terminating DEBUG: I0914 08:51:27.946476 16033 leveldb.cpp:176] Opened db in 2.593046ms DEBUG: I0914 08:51:27.947360 16033 leveldb.cpp:183] Compacted db in 856535ns DEBUG: I0914 08:51:27.947381 16033 leveldb.cpp:198] Created db iterator in 4046ns DEBUG: I0914 08:51:27.947393 16033 leveldb.cpp:204] Seeked to beginning of db in 883ns DEBUG: I0914 08:51:27.947402 16033 leveldb.cpp:273] Iterated through 0 keys in the db in 340ns DEBUG: I0914 08:51:27.947417 16033 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned DEBUG: I0914 08:51:27.947604 16060 recover.cpp:449] Starting replica recovery DEBUG: I0914 08:51:27.947742 16054 recover.cpp:475] Replica is in EMPTY status DEBUG: I0914 08:51:27.948607 16075 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request DEBUG: I0914 08:51:27.948755 16052 master.cpp:379] Master 20150914-085127-1711542956-33300-16033 (atlc-bev-05-sr1.corpdc.twttr.net) started on 172.18.4.102:33300 DEBUG: I0914 08:51:27.948770 16052 master.cpp:381] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_16KDgE/credentials" --framework_sorter="drf" --help="false" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_16KDgE/master" --zk_session_timeout="10secs" DEBUG: I0914 08:51:27.948905 16052 master.cpp:426] Master only allowing authenticated frameworks to register DEBUG: I0914 08:51:27.948912 16052 master.cpp:431] Master only allowing authenticated slaves to register DEBUG: I0914 08:51:27.948918 16052 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_16KDgE/credentials' DEBUG: I0914 08:51:27.949041 16053 recover.cpp:195] Received a recover response from a replica in EMPTY status DEBUG: I0914 08:51:27.949046 16052 master.cpp:470] Using default 'crammd5' authenticator DEBUG: I0914 08:51:27.949105 16052 master.cpp:507] Authorization enabled DEBUG: I0914 08:51:27.949486 16069 recover.cpp:566] Updating replica status to STARTING DEBUG: I0914 08:51:27.949867 16053 master.cpp:1594] The newly elected leader is master@172.18.4.102:33300 with id 20150914-085127-1711542956-33300-16033 DEBUG: I0914 08:51:27.949882 16053 master.cpp:1607] Elected as the leading master! DEBUG: I0914 08:51:27.949888 16053 master.cpp:1367] Recovering from registrar DEBUG: I0914 08:51:27.950093 16063 registrar.cpp:309] Recovering registrar DEBUG: I0914 08:51:27.950223 16054 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 418878ns DEBUG: I0914 08:51:27.950238 16054 replica.cpp:323] Persisted replica status to STARTING DEBUG: I0914 08:51:27.950333 16048 recover.cpp:475] Replica is in STARTING status DEBUG: I0914 08:51:27.950923 16075 replica.cpp:641] Replica in STARTING status received a broadcasted recover request DEBUG: I0914 08:51:27.951014 16055 recover.cpp:195] Received a recover response from a replica in STARTING status DEBUG: I0914 08:51:27.951215 16058 recover.cpp:566] Updating replica status to VOTING DEBUG: I0914 08:51:27.951720 16061 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 282248ns DEBUG: I0914 08:51:27.951736 16061 replica.cpp:323] Persisted replica status to VOTING DEBUG: I0914 08:51:27.951776 16061 recover.cpp:580] Successfully joined the Paxos group DEBUG: I0914 08:51:27.951824 16061 recover.cpp:464] Recover process terminated DEBUG: I0914 08:51:27.951992 16055 log.cpp:661] Attempting to start the writer DEBUG: I0914 08:51:27.952461 16058 replica.cpp:477] Replica received implicit promise request with proposal 1 DEBUG: I0914 08:51:27.952741 16058 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 261815ns DEBUG: I0914 08:51:27.952756 16058 replica.cpp:345] Persisted promised to 1 DEBUG: I0914 08:51:27.953050 16060 coordinator.cpp:231] Coordinator attemping to fill missing position DEBUG: I0914 08:51:27.953887 16075 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2 DEBUG: I0914 08:51:27.954156 16075 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 248629ns DEBUG: I0914 08:51:27.954171 16075 replica.cpp:679] Persisted action at 0 DEBUG: I0914 08:51:27.954769 16063 replica.cpp:511] Replica received write request for position 0 DEBUG: I0914 08:51:27.954795 16063 leveldb.cpp:438] Reading position from leveldb took 11655ns DEBUG: I0914 08:51:27.955054 16063 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 244314ns DEBUG: I0914 08:51:27.955068 16063 replica.cpp:679] Persisted action at 0 DEBUG: I0914 08:51:27.955427 16066 replica.cpp:658] Replica received learned notice for position 0 DEBUG: I0914 08:51:27.955548 16066 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 98477ns DEBUG: I0914 08:51:27.955561 16066 replica.cpp:679] Persisted action at 0 DEBUG: I0914 08:51:27.955569 16066 replica.cpp:664] Replica learned NOP action at position 0 DEBUG: I0914 08:51:27.955972 16057 log.cpp:677] Writer started with ending position 0 DEBUG: I0914 08:51:27.956434 16058 leveldb.cpp:438] Reading position from leveldb took 11996ns DEBUG: I0914 08:51:27.958369 16063 registrar.cpp:342] Successfully fetched the registry (0B) in 8.247808ms DEBUG: I0914 08:51:27.958401 16063 registrar.cpp:441] Applied 1 operations in 2735ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.960268 16063 log.cpp:685] Attempting to append 222 bytes to the log DEBUG: I0914 08:51:27.960330 16066 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1 DEBUG: I0914 08:51:27.960752 16050 replica.cpp:511] Replica received write request for position 1 DEBUG: I0914 08:51:27.961297 16050 leveldb.cpp:343] Persisting action (241 bytes) to leveldb took 525204ns DEBUG: I0914 08:51:27.961310 16050 replica.cpp:679] Persisted action at 1 DEBUG: I0914 08:51:27.961598 16068 replica.cpp:658] Replica received learned notice for position 1 DEBUG: I0914 08:51:27.961938 16068 leveldb.cpp:343] Persisting action (243 bytes) to leveldb took 320961ns DEBUG: I0914 08:51:27.961958 16068 replica.cpp:679] Persisted action at 1 DEBUG: I0914 08:51:27.961968 16068 replica.cpp:664] Replica learned APPEND action at position 1 DEBUG: I0914 08:51:27.962810 16052 registrar.cpp:486] Successfully updated the 'registry' in 4.381952ms DEBUG: I0914 08:51:27.962865 16054 log.cpp:704] Attempting to truncate the log to 1 DEBUG: I0914 08:51:27.962893 16052 registrar.cpp:372] Successfully recovered registrar DEBUG: I0914 08:51:27.963119 16066 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2 DEBUG: I0914 08:51:27.963510 16058 master.cpp:1404] Recovered 0 slaves from the Registry (183B) ; allowing 10mins for slaves to re-register DEBUG: I0914 08:51:27.964676 16064 replica.cpp:511] Replica received write request for position 2 DEBUG: I0914 08:51:27.964984 16064 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 289940ns DEBUG: I0914 08:51:27.964998 16064 replica.cpp:679] Persisted action at 2 DEBUG: I0914 08:51:27.965198 16065 replica.cpp:658] Replica received learned notice for position 2 DEBUG: I0914 08:51:27.965317 16065 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 99703ns DEBUG: I0914 08:51:27.965347 16065 leveldb.cpp:401] Deleting ~1 keys from leveldb took 13726ns DEBUG: I0914 08:51:27.965356 16065 replica.cpp:679] Persisted action at 2 DEBUG: I0914 08:51:27.965363 16065 replica.cpp:664] Replica learned TRUNCATE action at position 2 DEBUG: I0914 08:51:27.977643 16033 containerizer.cpp:160] Using isolation: posix/cpu,posix/mem,filesystem/posix DEBUG: I0914 08:51:27.979661 16068 slave.cpp:190] Slave started on 98)@172.18.4.102:33300 DEBUG: I0914 08:51:27.979681 16068 slave.cpp:191] Flags at startup: --appc_provisioner_backend="copy" --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/MasterSlaveReconciliationTest_ReconcileLostTask_KoudmJ/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --egress_unique_flow_per_container="false" --enforce_container_disk_quota="false" --ephemeral_ports_per_container="1024" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_KoudmJ/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/builddir/build/BUILD/mesos-0.25.0/src" --logbufsecs="0" --logging_level="INFO" --network_enable_socket_statistics_details="false" --network_enable_socket_statistics_summary="false" --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" --resource_monitoring_interval="1secs" --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" --version="false" --work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_KoudmJ" DEBUG: I0914 08:51:27.979918 16068 credentials.hpp:85] Loading credential for authentication from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_KoudmJ/credential' DEBUG: I0914 08:51:27.979996 16068 slave.cpp:321] Slave using credential for: test-principal DEBUG: I0914 08:51:27.980161 16068 slave.cpp:354] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] DEBUG: I0914 08:51:27.980473 16068 slave.cpp:384] Slave hostname: atlc-bev-05-sr1.corpdc.twttr.net DEBUG: I0914 08:51:27.980485 16068 slave.cpp:389] Slave checkpoint: true DEBUG: I0914 08:51:27.980801 16075 state.cpp:54] Recovering state from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_KoudmJ/meta' DEBUG: I0914 08:51:27.980911 16054 status_update_manager.cpp:202] Recovering status update manager DEBUG: I0914 08:51:27.981035 16059 containerizer.cpp:396] Recovering containerizer DEBUG: I0914 08:51:27.981577 16060 slave.cpp:4077] Finished recovery DEBUG: I0914 08:51:27.982142 16060 status_update_manager.cpp:176] Pausing sending status updates DEBUG: I0914 08:51:27.982173 16052 slave.cpp:692] New master detected at master@172.18.4.102:33300 DEBUG: I0914 08:51:27.982197 16052 slave.cpp:755] Authenticating with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.982205 16052 slave.cpp:760] Using default CRAM-MD5 authenticatee DEBUG: I0914 08:51:27.982245 16052 slave.cpp:728] Detecting new master DEBUG: I0914 08:51:27.982283 16069 authenticatee.cpp:115] Creating new client SASL connection DEBUG: I0914 08:51:27.982492 16057 master.cpp:4763] Authenticating slave(98)@172.18.4.102:33300 DEBUG: I0914 08:51:27.982584 16057 authenticator.cpp:92] Creating new server SASL connection DEBUG: I0914 08:51:27.982674 16054 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 DEBUG: I0914 08:51:27.982691 16054 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' DEBUG: I0914 08:51:27.982760 16068 authenticator.cpp:197] Received SASL authentication start DEBUG: I0914 08:51:27.982822 16068 authenticator.cpp:319] Authentication requires more steps DEBUG: I0914 08:51:27.982863 16068 authenticatee.cpp:252] Received SASL authentication step DEBUG: I0914 08:51:27.982906 16068 authenticator.cpp:225] Received SASL authentication step DEBUG: I0914 08:51:27.982942 16068 authenticator.cpp:311] Authentication success DEBUG: I0914 08:51:27.983000 16075 authenticatee.cpp:292] Authentication success DEBUG: I0914 08:51:27.983042 16057 master.cpp:4793] Successfully authenticated principal 'test-principal' at slave(98)@172.18.4.102:33300 DEBUG: I0914 08:51:27.983131 16052 slave.cpp:823] Successfully authenticated with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.983223 16057 master.cpp:3705] Registering slave at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with id 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.983320 16061 registrar.cpp:441] Applied 1 operations in 12168ns; attempting to update the 'registry' DEBUG: I0914 08:51:27.984428 16051 master.cpp:3693] Ignoring register slave message from slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) as admission is already in progress DEBUG: I0914 08:51:27.986776 16060 log.cpp:685] Attempting to append 413 bytes to the log DEBUG: I0914 08:51:27.986918 16064 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3 DEBUG: I0914 08:51:27.987124 16033 sched.cpp:164] Version: 0.25.0-rc0 DEBUG: I0914 08:51:27.987614 16054 sched.cpp:262] New master detected at master@172.18.4.102:33300 DEBUG: I0914 08:51:27.987637 16060 replica.cpp:511] Replica received write request for position 3 DEBUG: I0914 08:51:27.987756 16054 sched.cpp:318] Authenticating with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.987767 16054 sched.cpp:325] Using default CRAM-MD5 authenticatee DEBUG: I0914 08:51:27.987797 16060 leveldb.cpp:343] Persisting action (432 bytes) to leveldb took 129819ns DEBUG: I0914 08:51:27.987812 16060 replica.cpp:679] Persisted action at 3 DEBUG: I0914 08:51:27.987962 16075 authenticatee.cpp:115] Creating new client SASL connection DEBUG: I0914 08:51:27.988080 16072 replica.cpp:658] Replica received learned notice for position 3 DEBUG: I0914 08:51:27.988245 16050 master.cpp:4763] Authenticating scheduler-b6d1f76d-be8a-4073-8d35-f1b7460575bd@172.18.4.102:33300 DEBUG: I0914 08:51:27.988353 16067 authenticator.cpp:92] Creating new server SASL connection DEBUG: I0914 08:51:27.988416 16057 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 DEBUG: I0914 08:51:27.988435 16057 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' DEBUG: I0914 08:51:27.988472 16072 leveldb.cpp:343] Persisting action (434 bytes) to leveldb took 374637ns DEBUG: I0914 08:51:27.988492 16072 replica.cpp:679] Persisted action at 3 DEBUG: I0914 08:51:27.988497 16064 authenticator.cpp:197] Received SASL authentication start DEBUG: I0914 08:51:27.988503 16072 replica.cpp:664] Replica learned APPEND action at position 3 DEBUG: I0914 08:51:27.988553 16064 authenticator.cpp:319] Authentication requires more steps DEBUG: I0914 08:51:27.988729 16050 authenticatee.cpp:252] Received SASL authentication step DEBUG: I0914 08:51:27.988848 16061 authenticator.cpp:225] Received SASL authentication step DEBUG: I0914 08:51:27.988881 16061 authenticator.cpp:311] Authentication success DEBUG: I0914 08:51:27.988994 16067 registrar.cpp:486] Successfully updated the 'registry' in 5.652224ms DEBUG: I0914 08:51:27.989045 16063 master.cpp:4793] Successfully authenticated principal 'test-principal' at scheduler-b6d1f76d-be8a-4073-8d35-f1b7460575bd@172.18.4.102:33300 DEBUG: I0914 08:51:27.989096 16054 authenticatee.cpp:292] Authentication success DEBUG: I0914 08:51:27.989126 16058 log.cpp:704] Attempting to truncate the log to 3 DEBUG: I0914 08:51:27.989255 16072 sched.cpp:407] Successfully authenticated with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.989286 16066 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4 DEBUG: I0914 08:51:27.989316 16063 master.cpp:3768] Registered slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] DEBUG: I0914 08:51:27.989374 16052 hierarchical.hpp:543] Added slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) DEBUG: I0914 08:51:27.989399 16059 slave.cpp:867] Registered with master master@172.18.4.102:33300; given slave ID 20150914-085127-1711542956-33300-16033-S0 DEBUG: I0914 08:51:27.989481 16049 master.cpp:2163] Received SUBSCRIBE call for framework 'default' at scheduler-b6d1f76d-be8a-4073-8d35-f1b7460575bd@172.18.4.102:33300 DEBUG: I0914 08:51:27.989501 16048 status_update_manager.cpp:183] Resuming sending status updates DEBUG: I0914 08:51:27.989511 16049 master.cpp:1633] Authorizing framework principal 'test-principal' to receive offers for role '*' DEBUG: I0914 08:51:27.989730 16061 master.cpp:2233] Subscribing framework default with checkpointing disabled and capabilities [ ] DEBUG: I0914 08:51:27.989755 16056 replica.cpp:511] Replica received write request for position 4 DEBUG: I0914 08:51:27.989886 16059 slave.cpp:926] Forwarding total oversubscribed resources DEBUG: I0914 08:51:27.989902 16065 hierarchical.hpp:392] Added framework 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.990051 16061 master.cpp:4067] Received update of slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) with total oversubscribed resources DEBUG: I0914 08:51:27.990108 16056 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 333493ns DEBUG: I0914 08:51:27.990123 16056 replica.cpp:679] Persisted action at 4 DEBUG: I0914 08:51:27.990159 16048 hierarchical.hpp:603] Slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) DEBUG: I0914 08:51:27.990188 16061 master.cpp:4682] Sending 1 offers to framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-b6d1f76d-be8a-4073-8d35-f1b7460575bd@172.18.4.102:33300 DEBUG: I0914 08:51:27.990197 16068 sched.cpp:640] Framework registered with 20150914-085127-1711542956-33300-16033-0000 DEBUG: I0914 08:51:27.990546 16075 replica.cpp:658] Replica received learned notice for position 4 DEBUG: I0914 08:51:27.990684 16075 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 118077ns DEBUG: I0914 08:51:27.990726 16075 leveldb.cpp:401] Deleting ~2 keys from leveldb took 24036ns DEBUG: I0914 08:51:27.990738 16075 replica.cpp:679] Persisted action at 4 DEBUG: I0914 08:51:27.990746 16075 replica.cpp:664] Replica learned TRUNCATE action at position 4 DEBUG: I0914 08:51:27.991216 16060 master.cpp:2808] Processing ACCEPT call for offers: [ 20150914-085127-1711542956-33300-16033-O0 ] on slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) for framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-b6d1f76d-be8a-4073-8d35-f1b7460575bd@172.18.4.102:33300 DEBUG: I0914 08:51:27.991237 16060 master.cpp:2639] Authorizing framework principal 'test-principal' to launch task 1 as user 'mockbuild' DEBUG: W0914 08:51:27.991605 16064 validation.cpp:419] 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. DEBUG: W0914 08:51:27.991628 16064 validation.cpp:431] 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. DEBUG: I0914 08:51:27.991700 16064 master.hpp:173] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150914-085127-1711542956-33300-16033-S0 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.991739 16064 master.cpp:3138] Launching task 1 of framework 20150914-085127-1711542956-33300-16033-0000 (default) at scheduler-b6d1f76d-be8a-4073-8d35-f1b7460575bd@172.18.4.102:33300 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.994158 16057 status_update_manager.cpp:176] Pausing sending status updates DEBUG: I0914 08:51:27.994238 16048 slave.cpp:692] New master detected at master@172.18.4.102:33300 DEBUG: I0914 08:51:27.994257 16048 slave.cpp:755] Authenticating with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.994264 16048 slave.cpp:760] Using default CRAM-MD5 authenticatee DEBUG: I0914 08:51:27.994321 16048 slave.cpp:728] Detecting new master DEBUG: I0914 08:51:27.994336 16055 authenticatee.cpp:115] Creating new client SASL connection DEBUG: I0914 08:51:27.994559 16058 master.cpp:4763] Authenticating slave(98)@172.18.4.102:33300 DEBUG: I0914 08:51:27.994662 16058 authenticator.cpp:92] Creating new server SASL connection DEBUG: I0914 08:51:27.994753 16075 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5 DEBUG: I0914 08:51:27.994776 16075 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5' DEBUG: I0914 08:51:27.994853 16067 authenticator.cpp:197] Received SASL authentication start DEBUG: I0914 08:51:27.994909 16067 authenticator.cpp:319] Authentication requires more steps DEBUG: I0914 08:51:27.994959 16052 authenticatee.cpp:252] Received SASL authentication step DEBUG: I0914 08:51:27.995004 16052 authenticator.cpp:225] Received SASL authentication step DEBUG: I0914 08:51:27.995028 16052 authenticator.cpp:311] Authentication success DEBUG: I0914 08:51:27.995091 16068 authenticatee.cpp:292] Authentication success DEBUG: I0914 08:51:27.995105 16059 master.cpp:4793] Successfully authenticated principal 'test-principal' at slave(98)@172.18.4.102:33300 DEBUG: I0914 08:51:27.995373 16059 slave.cpp:823] Successfully authenticated with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.995561 16048 master.cpp:3842] Re-registering slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: W0914 08:51:27.995589 16048 master.cpp:4860] Task 1 of framework 20150914-085127-1711542956-33300-16033-0000 unknown to the slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) during re-registration: reconciling with the slave DEBUG: W0914 08:51:27.995645 16048 master.cpp:4942] Executor default of framework 20150914-085127-1711542956-33300-16033-0000 possibly unknown to the slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.995679 16048 master.cpp:5742] Removing executor 'default' with resources of framework 20150914-085127-1711542956-33300-16033-0000 on slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.995733 16048 master.cpp:4005] Sending updated checkpointed resources to slave 20150914-085127-1711542956-33300-16033-S0 at slave(98)@172.18.4.102:33300 (atlc-bev-05-sr1.corpdc.twttr.net) DEBUG: I0914 08:51:27.995828 16058 slave.cpp:967] Re-registered with master master@172.18.4.102:33300 DEBUG: I0914 08:51:27.995910 16058 slave.cpp:1003] Forwarding total oversubscribed resources DEBUG: I0914 08:51:27.995923 16064 status_update_manager.cpp:183] Resuming sending status updates DEBUG: ../3rdparty/libprocess/include/process/gmock.hpp:365: Failure DEBUG: Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A<const MessageEvent&>()))... DEBUG: Expected args: message matcher (8-byte object <C8-EF 02-DC 7C-7F 00-00>, 1-byte object <58>, 1) DEBUG: Expected: to be called once DEBUG: Actual: never called - unsatisfied and active DEBUG: [ FAILED ] MasterSlaveReconciliationTest.ReconcileLostTask (22495 ms) {code} > MasterSlaveReconciliationTest.ReconcileLostTask test is flaky > ------------------------------------------------------------- > > Key: MESOS-3422 > URL: https://issues.apache.org/jira/browse/MESOS-3422 > Project: Mesos > Issue Type: Bug > Components: technical debt, test > Affects Versions: 0.25.0 > Environment: CentOS > Reporter: Vinod Kone > > [==========] Running 1 test from 1 test case. > [----------] Global test environment set-up. > [----------] 1 test from MasterSlaveReconciliationTest > [ RUN ] MasterSlaveReconciliationTest.ReconcileLostTask > Using temporary directory > '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn' > I0915 22:28:40.800787 3733 leveldb.cpp:176] Opened db in 252.206266ms > I0915 22:28:40.851069 3733 leveldb.cpp:183] Compacted db in 50.197346ms > I0915 22:28:40.851210 3733 leveldb.cpp:198] Created db iterator in 63324ns > I0915 22:28:40.851256 3733 leveldb.cpp:204] Seeked to beginning of db in > 4562ns > I0915 22:28:40.851286 3733 leveldb.cpp:273] Iterated through 0 keys in the > db in 322ns > I0915 22:28:40.871953 3733 replica.cpp:744] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0915 22:28:40.886368 3756 recover.cpp:449] Starting replica recovery > I0915 22:28:40.903333 3756 recover.cpp:475] Replica is in EMPTY status > I0915 22:28:40.916332 3759 replica.cpp:641] Replica in EMPTY status received > a broadcasted recover request > I0915 22:28:40.917351 3756 recover.cpp:195] Received a recover response from > a replica in EMPTY status > I0915 22:28:40.918557 3755 recover.cpp:566] Updating replica status to > STARTING > I0915 22:28:40.928189 3759 master.cpp:380] Master > 20150915-222840-16842879-54960-3733 (devstack007.cn.ibm.com) started on > 127.0.1.1:54960 > I0915 22:28:40.928261 3759 master.cpp:382] Flags at startup: --acls="" > --allocation_interval="1secs" --allocator="HierarchicalDRF" > --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" > --authorizers="local" > --credentials="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn/credentials" > --framework_sorter="drf" --help="false" --initialize_driver_logging="true" > --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" > --max_slave_ping_timeouts="5" --quiet="false" > --recovery_slave_removal_limit="100%" --registry="replicated_log" > --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" > --registry_strict="true" --root_submissions="true" > --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" > --user_sorter="drf" --version="false" > --webui_dir="/usr/local/share/mesos/webui" > --work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn/master" > --zk_session_timeout="10secs" > I0915 22:28:40.993895 3759 master.cpp:427] Master only allowing > authenticated frameworks to register > I0915 22:28:40.993962 3759 master.cpp:432] Master only allowing > authenticated slaves to register > I0915 22:28:40.994010 3759 credentials.hpp:37] Loading credentials for > authentication from > '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_2tUQZn/credentials' > I0915 22:28:40.994776 3759 master.cpp:471] Using default 'crammd5' > authenticator > I0915 22:28:40.995053 3759 authenticator.cpp:512] Initializing server SASL > I0915 22:28:41.009496 3757 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 90.341573ms > I0915 22:28:41.009570 3757 replica.cpp:323] Persisted replica status to > STARTING > I0915 22:28:41.010040 3756 recover.cpp:475] Replica is in STARTING status > I0915 22:28:41.011255 3757 replica.cpp:641] Replica in STARTING status > received a broadcasted recover request > I0915 22:28:41.011551 3752 recover.cpp:195] Received a recover response from > a replica in STARTING status > I0915 22:28:41.012073 3756 recover.cpp:566] Updating replica status to VOTING > I0915 22:28:41.084720 3753 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 72.469042ms > I0915 22:28:41.084803 3753 replica.cpp:323] Persisted replica status to > VOTING > I0915 22:28:41.084935 3752 recover.cpp:580] Successfully joined the Paxos > group > I0915 22:28:41.085227 3752 recover.cpp:464] Recover process terminated > I0915 22:28:41.191287 3759 auxprop.cpp:66] Initialized in-memory auxiliary > property plugin > I0915 22:28:41.191455 3759 master.cpp:508] Authorization enabled > I0915 22:28:41.192039 3758 hierarchical.hpp:408] Initialized hierarchical > allocator process > I0915 22:28:41.210978 3752 whitelist_watcher.cpp:79] No whitelist given > I0915 22:28:41.226894 3757 master.cpp:1605] The newly elected leader is > master@127.0.1.1:54960 with id 20150915-222840-16842879-54960-3733 > I0915 22:28:41.227022 3757 master.cpp:1618] Elected as the leading master! > I0915 22:28:41.227073 3757 master.cpp:1378] Recovering from registrar > I0915 22:28:41.227442 3756 registrar.cpp:309] Recovering registrar > I0915 22:28:41.228864 3759 log.cpp:661] Attempting to start the writer > I0915 22:28:41.231155 3754 replica.cpp:477] Replica received implicit > promise request with proposal 1 > I0915 22:28:41.276180 3754 leveldb.cpp:306] Persisting metadata (8 bytes) to > leveldb took 44.960628ms > I0915 22:28:41.276265 3754 replica.cpp:345] Persisted promised to 1 > I0915 22:28:41.277185 3755 coordinator.cpp:231] Coordinator attemping to > fill missing position > I0915 22:28:41.279559 3755 replica.cpp:378] Replica received explicit > promise request for position 0 with proposal 2 > I0915 22:28:41.317904 3755 leveldb.cpp:343] Persisting action (8 bytes) to > leveldb took 38.28625ms > I0915 22:28:41.317952 3755 replica.cpp:679] Persisted action at 0 > I0915 22:28:41.318975 3756 replica.cpp:511] Replica received write request > for position 0 > I0915 22:28:41.319077 3756 leveldb.cpp:438] Reading position from leveldb > took 48432ns > I0915 22:28:41.351290 3756 leveldb.cpp:343] Persisting action (14 bytes) to > leveldb took 32.131668ms > I0915 22:28:41.351372 3756 replica.cpp:679] Persisted action at 0 > I0915 22:28:41.352147 3755 replica.cpp:658] Replica received learned notice > for position 0 > I0915 22:28:41.384781 3755 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 32.568205ms > I0915 22:28:41.384858 3755 replica.cpp:679] Persisted action at 0 > I0915 22:28:41.384902 3755 replica.cpp:664] Replica learned NOP action at > position 0 > I0915 22:28:41.385823 3753 log.cpp:677] Writer started with ending position 0 > I0915 22:28:41.388413 3754 leveldb.cpp:438] Reading position from leveldb > took 41960ns > I0915 22:28:41.391221 3759 registrar.cpp:342] Successfully fetched the > registry (0B) in 163.655936ms > I0915 22:28:41.391530 3759 registrar.cpp:441] Applied 1 operations in > 83084ns; attempting to update the 'registry' > I0915 22:28:41.395333 3752 log.cpp:685] Attempting to append 188 bytes to > the log > I0915 22:28:41.395625 3757 coordinator.cpp:341] Coordinator attempting to > write APPEND action at position 1 > I0915 22:28:41.396404 3753 replica.cpp:511] Replica received write request > for position 1 > I0915 22:28:41.434862 3753 leveldb.cpp:343] Persisting action (207 bytes) to > leveldb took 38.376695ms > I0915 22:28:41.434942 3753 replica.cpp:679] Persisted action at 1 > I0915 22:28:41.435797 3758 replica.cpp:658] Replica received learned notice > for position 1 > I0915 22:28:41.484905 3758 leveldb.cpp:343] Persisting action (209 bytes) to > leveldb took 49.03218ms > I0915 22:28:41.484977 3758 replica.cpp:679] Persisted action at 1 > I0915 22:28:41.485021 3758 replica.cpp:664] Replica learned APPEND action at > position 1 > I0915 22:28:41.486634 3759 registrar.cpp:486] Successfully updated the > 'registry' in 94.96704ms > I0915 22:28:41.486788 3759 registrar.cpp:372] Successfully recovered > registrar > I0915 22:28:41.486871 3752 log.cpp:704] Attempting to truncate the log to 1 > I0915 22:28:41.487041 3753 coordinator.cpp:341] Coordinator attempting to > write TRUNCATE action at position 2 > I0915 22:28:41.487397 3758 master.cpp:1415] Recovered 0 slaves from the > Registry (149B) ; allowing 10mins for slaves to re-register > I0915 22:28:41.488390 3754 replica.cpp:511] Replica received write request > for position 2 > I0915 22:28:41.518287 3754 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 29.818009ms > I0915 22:28:41.518383 3754 replica.cpp:679] Persisted action at 2 > I0915 22:28:41.519301 3753 replica.cpp:658] Replica received learned notice > for position 2 > I0915 22:28:41.551661 3753 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 32.172645ms > I0915 22:28:41.551758 3753 leveldb.cpp:401] Deleting ~1 keys from leveldb > took 45547ns > I0915 22:28:41.551798 3753 replica.cpp:679] Persisted action at 2 > I0915 22:28:41.551862 3753 replica.cpp:664] Replica learned TRUNCATE action > at position 2 > I0915 22:28:41.582856 3733 containerizer.cpp:160] Using isolation: > posix/cpu,posix/mem,filesystem/posix > I0915 22:28:41.612773 3752 slave.cpp:190] Slave started on 1)@127.0.1.1:54960 > I0915 22:28:41.612828 3752 slave.cpp:191] Flags at startup: > --appc_provisioner_backend="copy" --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/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_kill_orphans="true" --docker_remove_delay="6hrs" > --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" > --launcher_dir="/home/gyliu/src/mesos/bug-fix/mesos/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" --resource_monitoring_interval="1secs" > --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" --version="false" > --work_dir="/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7" > I0915 22:28:41.613301 3752 credentials.hpp:85] Loading credential for > authentication from > '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/credential' > I0915 22:28:41.613534 3752 slave.cpp:321] Slave using credential for: > test-principal > I0915 22:28:41.614586 3752 slave.cpp:354] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I0915 22:28:41.614718 3752 slave.cpp:384] Slave hostname: > devstack007.cn.ibm.com > I0915 22:28:41.614749 3752 slave.cpp:389] Slave checkpoint: true > I0915 22:28:41.616605 3756 state.cpp:54] Recovering state from > '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/meta' > I0915 22:28:41.617005 3756 status_update_manager.cpp:202] Recovering status > update manager > I0915 22:28:41.617219 3756 containerizer.cpp:396] Recovering containerizer > I0915 22:28:41.618137 3733 sched.cpp:164] Version: 0.25.0 > I0915 22:28:41.620059 3752 sched.cpp:262] New master detected at > master@127.0.1.1:54960 > I0915 22:28:41.620291 3752 sched.cpp:318] Authenticating with master > master@127.0.1.1:54960 > I0915 22:28:41.620337 3752 sched.cpp:325] Using default CRAM-MD5 > authenticatee > I0915 22:28:41.620400 3758 slave.cpp:4077] Finished recovery > I0915 22:28:41.620708 3759 authenticatee.cpp:91] Initializing client SASL > I0915 22:28:41.620842 3758 slave.cpp:4234] Querying resource estimator for > oversubscribable resources > I0915 22:28:41.620873 3759 authenticatee.cpp:115] Creating new client SASL > connection > I0915 22:28:41.621410 3752 master.cpp:5089] Authenticating > scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 > I0915 22:28:41.621544 3757 authenticator.cpp:407] Starting authentication > session for crammd5_authenticatee(1)@127.0.1.1:54960 > I0915 22:28:41.621572 3758 slave.cpp:692] New master detected at > master@127.0.1.1:54960 > I0915 22:28:41.621656 3758 slave.cpp:755] Authenticating with master > master@127.0.1.1:54960 > I0915 22:28:41.621686 3758 slave.cpp:760] Using default CRAM-MD5 > authenticatee > I0915 22:28:41.621772 3752 status_update_manager.cpp:176] Pausing sending > status updates > I0915 22:28:41.621888 3755 authenticatee.cpp:115] Creating new client SASL > connection > I0915 22:28:41.621942 3758 slave.cpp:728] Detecting new master > I0915 22:28:41.622141 3758 slave.cpp:4248] Received oversubscribable > resources from the resource estimator > I0915 22:28:41.621975 3753 authenticator.cpp:92] Creating new server SASL > connection > I0915 22:28:41.622253 3754 master.cpp:5089] Authenticating > slave(1)@127.0.1.1:54960 > I0915 22:28:41.622418 3756 authenticator.cpp:407] Starting authentication > session for crammd5_authenticatee(2)@127.0.1.1:54960 > I0915 22:28:41.622560 3757 authenticator.cpp:92] Creating new server SASL > connection > I0915 22:28:41.624449 3759 authenticatee.cpp:206] Received SASL > authentication mechanisms: CRAM-MD5 > I0915 22:28:41.624451 3755 authenticatee.cpp:206] Received SASL > authentication mechanisms: CRAM-MD5 > I0915 22:28:41.624485 3759 authenticatee.cpp:232] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0915 22:28:41.624511 3755 authenticatee.cpp:232] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0915 22:28:41.624595 3759 authenticator.cpp:197] Received SASL > authentication start > I0915 22:28:41.624606 3755 authenticator.cpp:197] Received SASL > authentication start > I0915 22:28:41.624666 3759 authenticator.cpp:319] Authentication requires > more steps > I0915 22:28:41.624698 3755 authenticator.cpp:319] Authentication requires > more steps > I0915 22:28:41.624742 3759 authenticatee.cpp:252] Received SASL > authentication step > I0915 22:28:41.624788 3755 authenticatee.cpp:252] Received SASL > authentication step > I0915 22:28:41.624846 3759 authenticator.cpp:225] Received SASL > authentication step > I0915 22:28:41.624876 3759 auxprop.cpp:102] Request to lookup properties for > user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: > 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I0915 22:28:41.624879 3755 authenticator.cpp:225] Received SASL > authentication step > I0915 22:28:41.624898 3759 auxprop.cpp:174] Looking up auxiliary property > '*userPassword' > I0915 22:28:41.624927 3755 auxprop.cpp:102] Request to lookup properties for > user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: > 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I0915 22:28:41.624956 3755 auxprop.cpp:174] Looking up auxiliary property > '*userPassword' > I0915 22:28:41.625015 3759 auxprop.cpp:174] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0915 22:28:41.625020 3755 auxprop.cpp:174] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0915 22:28:41.625049 3759 auxprop.cpp:102] Request to lookup properties for > user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: > 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I0915 22:28:41.625067 3759 auxprop.cpp:124] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0915 22:28:41.625071 3755 auxprop.cpp:102] Request to lookup properties for > user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: > 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I0915 22:28:41.625080 3759 auxprop.cpp:124] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0915 22:28:41.625102 3755 auxprop.cpp:124] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0915 22:28:41.625118 3759 authenticator.cpp:311] Authentication success > I0915 22:28:41.625123 3755 auxprop.cpp:124] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0915 22:28:41.625154 3755 authenticator.cpp:311] Authentication success > I0915 22:28:41.625191 3754 authenticatee.cpp:292] Authentication success > I0915 22:28:41.625288 3753 authenticatee.cpp:292] Authentication success > I0915 22:28:41.625375 3752 master.cpp:5119] Successfully authenticated > principal 'test-principal' at > scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 > I0915 22:28:41.625401 3759 authenticator.cpp:425] Authentication session > cleanup for crammd5_authenticatee(1)@127.0.1.1:54960 > I0915 22:28:41.625497 3754 sched.cpp:407] Successfully authenticated with > master master@127.0.1.1:54960 > I0915 22:28:41.625535 3754 sched.cpp:714] Sending SUBSCRIBE call to > master@127.0.1.1:54960 > I0915 22:28:41.625500 3752 master.cpp:5119] Successfully authenticated > principal 'test-principal' at slave(1)@127.0.1.1:54960 > I0915 22:28:41.625704 3759 authenticator.cpp:425] Authentication session > cleanup for crammd5_authenticatee(2)@127.0.1.1:54960 > I0915 22:28:41.625695 3754 sched.cpp:747] Will retry registration in > 810.177326ms if necessary > I0915 22:28:41.625833 3755 master.cpp:2174] Received SUBSCRIBE call for > framework 'default' at > scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 > I0915 22:28:41.625833 3758 slave.cpp:823] Successfully authenticated with > master master@127.0.1.1:54960 > I0915 22:28:41.625954 3755 master.cpp:1644] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I0915 22:28:41.626005 3758 slave.cpp:1217] Will retry registration in > 1.558741ms if necessary > I0915 22:28:41.628494 3758 slave.cpp:1217] Will retry registration in > 4.690825ms if necessary > I0915 22:28:41.634006 3756 slave.cpp:1217] Will retry registration in > 12.908225ms if necessary > I0915 22:28:41.636726 3755 master.cpp:3816] Registering slave at > slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) with id > 20150915-222840-16842879-54960-3733-S0 > I0915 22:28:41.637073 3755 master.cpp:2244] Subscribing framework default > with checkpointing disabled and capabilities [ ] > I0915 22:28:41.637322 3753 registrar.cpp:441] Applied 1 operations in > 55510ns; attempting to update the 'registry' > I0915 22:28:41.637547 3752 hierarchical.hpp:453] Added framework > 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.637742 3755 master.cpp:3804] Ignoring register slave message > from slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) as admission is > already in progress > I0915 22:28:41.637774 3759 sched.cpp:641] Framework registered with > 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.637926 3752 hierarchical.hpp:1147] No resources available to > allocate! > I0915 22:28:41.638077 3752 hierarchical.hpp:1230] No inverse offers to send > out! > I0915 22:28:41.638087 3755 master.cpp:3804] Ignoring register slave message > from slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) as admission is > already in progress > I0915 22:28:41.638108 3752 hierarchical.hpp:1047] Performed allocation for 0 > slaves in 202137ns > I0915 22:28:41.638044 3759 sched.cpp:655] Scheduler::registered took 39399ns > I0915 22:28:41.640064 3754 log.cpp:685] Attempting to append 366 bytes to > the log > I0915 22:28:41.640266 3755 coordinator.cpp:341] Coordinator attempting to > write APPEND action at position 3 > I0915 22:28:41.640923 3756 replica.cpp:511] Replica received write request > for position 3 > I0915 22:28:41.647588 3752 slave.cpp:1217] Will retry registration in > 148.576472ms if necessary > I0915 22:28:41.647784 3758 master.cpp:3804] Ignoring register slave message > from slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) as admission is > already in progress > I0915 22:28:41.693835 3756 leveldb.cpp:343] Persisting action (385 bytes) to > leveldb took 52.865341ms > I0915 22:28:41.693887 3756 replica.cpp:679] Persisted action at 3 > I0915 22:28:41.694504 3752 replica.cpp:658] Replica received learned notice > for position 3 > I0915 22:28:41.727273 3752 leveldb.cpp:343] Persisting action (387 bytes) to > leveldb took 32.694232ms > I0915 22:28:41.727345 3752 replica.cpp:679] Persisted action at 3 > I0915 22:28:41.727392 3752 replica.cpp:664] Replica learned APPEND action at > position 3 > I0915 22:28:41.728603 3754 registrar.cpp:486] Successfully updated the > 'registry' in 91.195136ms > I0915 22:28:41.728809 3755 log.cpp:704] Attempting to truncate the log to 3 > I0915 22:28:41.728914 3754 coordinator.cpp:341] Coordinator attempting to > write TRUNCATE action at position 4 > I0915 22:28:41.729423 3753 replica.cpp:511] Replica received write request > for position 4 > I0915 22:28:41.729729 3755 slave.cpp:3105] Received ping from > slave-observer(1)@127.0.1.1:54960 > I0915 22:28:41.729907 3758 master.cpp:3884] Registered slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I0915 22:28:41.730042 3755 hierarchical.hpp:612] Added slave > 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) with > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I0915 22:28:41.730104 3754 slave.cpp:867] Registered with master > master@127.0.1.1:54960; given slave ID 20150915-222840-16842879-54960-3733-S0 > I0915 22:28:41.730140 3754 fetcher.cpp:77] Clearing fetcher cache > I0915 22:28:41.730262 3757 status_update_manager.cpp:183] Resuming sending > status updates > I0915 22:28:41.730599 3755 hierarchical.hpp:1230] No inverse offers to send > out! > I0915 22:28:41.730633 3755 hierarchical.hpp:1065] Performed allocation for > slave 20150915-222840-16842879-54960-3733-S0 in 548692ns > I0915 22:28:41.731081 3759 master.cpp:4918] Sending 1 offers to framework > 20150915-222840-16842879-54960-3733-0000 (default) at > scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 > I0915 22:28:41.731506 3759 sched.cpp:811] Scheduler::resourceOffers took > 76181ns > I0915 22:28:41.733994 3758 master.cpp:2878] Processing ACCEPT call for > offers: [ 20150915-222840-16842879-54960-3733-O0 ] on slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) for framework > 20150915-222840-16842879-54960-3733-0000 (default) at > scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 > I0915 22:28:41.734100 3758 master.cpp:2682] Authorizing framework principal > 'test-principal' to launch task 1 as user 'gyliu' > W0915 22:28:41.736322 3758 validation.cpp:419] 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. > W0915 22:28:41.736408 3758 validation.cpp:431] 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. > I0915 22:28:41.737035 3758 master.hpp:176] Adding task 1 with resources > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave > 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) > I0915 22:28:41.737259 3758 master.cpp:3208] Launching task 1 of framework > 20150915-222840-16842879-54960-3733-0000 (default) at > scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 with resources > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) > I0915 22:28:41.820271 3754 slave.cpp:890] Checkpointing SlaveInfo to > '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tymaz7/meta/slaves/20150915-222840-16842879-54960-3733-S0/slave.info' > I0915 22:28:41.820550 3754 slave.cpp:926] Forwarding total oversubscribed > resources > I0915 22:28:41.821171 3756 master.cpp:4226] Received update of slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) with total oversubscribed resources > I0915 22:28:41.821429 3755 hierarchical.hpp:672] Slave > 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000]) > I0915 22:28:41.821674 3755 hierarchical.hpp:1147] No resources available to > allocate! > I0915 22:28:41.821709 3755 hierarchical.hpp:1230] No inverse offers to send > out! > I0915 22:28:41.821738 3755 hierarchical.hpp:1065] Performed allocation for > slave 20150915-222840-16842879-54960-3733-S0 in 264094ns > I0915 22:28:41.822713 3756 status_update_manager.cpp:176] Pausing sending > status updates > I0915 22:28:41.822727 3758 slave.cpp:692] New master detected at > master@127.0.1.1:54960 > I0915 22:28:41.822803 3758 slave.cpp:755] Authenticating with master > master@127.0.1.1:54960 > I0915 22:28:41.822823 3758 slave.cpp:760] Using default CRAM-MD5 > authenticatee > I0915 22:28:41.822923 3758 slave.cpp:728] Detecting new master > I0915 22:28:41.823016 3752 authenticatee.cpp:115] Creating new client SASL > connection > I0915 22:28:41.823370 3754 master.cpp:5089] Authenticating > slave(1)@127.0.1.1:54960 > I0915 22:28:41.823542 3758 authenticator.cpp:407] Starting authentication > session for crammd5_authenticatee(3)@127.0.1.1:54960 > I0915 22:28:41.823711 3752 authenticator.cpp:92] Creating new server SASL > connection > I0915 22:28:41.823891 3756 authenticatee.cpp:206] Received SASL > authentication mechanisms: CRAM-MD5 > I0915 22:28:41.823927 3756 authenticatee.cpp:232] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0915 22:28:41.824025 3758 authenticator.cpp:197] Received SASL > authentication start > I0915 22:28:41.824177 3758 authenticator.cpp:319] Authentication requires > more steps > I0915 22:28:41.824311 3758 authenticatee.cpp:252] Received SASL > authentication step > I0915 22:28:41.824445 3758 authenticator.cpp:225] Received SASL > authentication step > I0915 22:28:41.824507 3758 auxprop.cpp:102] Request to lookup properties for > user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: > 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I0915 22:28:41.824544 3758 auxprop.cpp:174] Looking up auxiliary property > '*userPassword' > I0915 22:28:41.824609 3758 auxprop.cpp:174] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0915 22:28:41.824658 3758 auxprop.cpp:102] Request to lookup properties for > user: 'test-principal' realm: 'devstack007.cn.ibm.com' server FQDN: > 'devstack007.cn.ibm.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I0915 22:28:41.824692 3758 auxprop.cpp:124] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0915 22:28:41.824717 3758 auxprop.cpp:124] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0915 22:28:41.824753 3758 authenticator.cpp:311] Authentication success > I0915 22:28:41.824874 3756 authenticatee.cpp:292] Authentication success > I0915 22:28:41.824914 3757 master.cpp:5119] Successfully authenticated > principal 'test-principal' at slave(1)@127.0.1.1:54960 > I0915 22:28:41.825027 3759 authenticator.cpp:425] Authentication session > cleanup for crammd5_authenticatee(3)@127.0.1.1:54960 > I0915 22:28:41.825168 3758 slave.cpp:823] Successfully authenticated with > master master@127.0.1.1:54960 > I0915 22:28:41.825443 3758 slave.cpp:1217] Will retry registration in > 13.419746ms if necessary > I0915 22:28:41.825734 3752 master.cpp:3976] Re-registering slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) > W0915 22:28:41.826159 3752 master.cpp:5186] Task 1 of framework > 20150915-222840-16842879-54960-3733-0000 unknown to the slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) during re-registration: reconciling with the slave > W0915 22:28:41.826668 3752 master.cpp:5268] Executor default of framework > 20150915-222840-16842879-54960-3733-0000 possibly unknown to the slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) > I0915 22:28:41.826745 3756 slave.cpp:967] Re-registered with master > master@127.0.1.1:54960 > I0915 22:28:41.826797 3752 master.cpp:6118] Removing executor 'default' with > resources of framework 20150915-222840-16842879-54960-3733-0000 on slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) > I0915 22:28:41.826820 3757 status_update_manager.cpp:183] Resuming sending > status updates > I0915 22:28:41.826843 3756 slave.cpp:1003] Forwarding total oversubscribed > resources > W0915 22:28:41.827033 3756 slave.cpp:1043] Slave reconciling task 1 of > framework 20150915-222840-16842879-54960-3733-0000 in state TASK_LOST: task > unknown to the slave > I0915 22:28:41.827244 3752 master.cpp:4164] Sending updated checkpointed > resources to slave 20150915-222840-16842879-54960-3733-S0 at > slave(1)@127.0.1.1:54960 (devstack007.cn.ibm.com) > I0915 22:28:41.827461 3752 master.cpp:4226] Received update of slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) with total oversubscribed resources > I0915 22:28:41.827873 3757 hierarchical.hpp:672] Slave > 20150915-222840-16842879-54960-3733-S0 (devstack007.cn.ibm.com) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000]) > I0915 22:28:41.828115 3757 hierarchical.hpp:1147] No resources available to > allocate! > I0915 22:28:41.828151 3757 hierarchical.hpp:1230] No inverse offers to send > out! > I0915 22:28:41.828176 3757 hierarchical.hpp:1065] Performed allocation for > slave 20150915-222840-16842879-54960-3733-S0 in 260424ns > I0915 22:28:41.828800 3752 status_update_manager.cpp:322] Received status > update TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of > framework 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.828882 3752 status_update_manager.cpp:499] Creating > StatusUpdate stream for task 1 of framework > 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.829025 3756 slave.cpp:2235] Updated checkpointed resources > from to > I0915 22:28:41.829366 3752 status_update_manager.cpp:376] Forwarding update > TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of > framework 20150915-222840-16842879-54960-3733-0000 to the slave > I0915 22:28:41.829633 3755 slave.cpp:2983] Forwarding the update TASK_LOST > (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework > 20150915-222840-16842879-54960-3733-0000 to master@127.0.1.1:54960 > I0915 22:28:41.829941 3755 slave.cpp:2907] Status update manager > successfully handled status update TASK_LOST (UUID: > 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework > 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.830066 3758 master.cpp:4366] Status update TASK_LOST (UUID: > 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework > 20150915-222840-16842879-54960-3733-0000 from slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) > I0915 22:28:41.830114 3758 master.cpp:4405] Forwarding status update > TASK_LOST (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of > framework 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.830272 3758 master.cpp:6021] Updating the latest state of > task 1 of framework 20150915-222840-16842879-54960-3733-0000 to TASK_LOST > I0915 22:28:41.830363 3759 sched.cpp:918] Scheduler::statusUpdate took > 54887ns > I0915 22:28:41.830675 3757 hierarchical.hpp:954] Recovered cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave > 20150915-222840-16842879-54960-3733-S0 from framework > 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.835749 3753 leveldb.cpp:343] Persisting action (16 bytes) to > leveldb took 106.276892ms > I0915 22:28:41.835824 3753 replica.cpp:679] Persisted action at 4 > I0915 22:28:41.836457 3753 replica.cpp:658] Replica received learned notice > for position 4 > I0915 22:28:41.836736 3758 master.cpp:6089] Removing task 1 with resources > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework > 20150915-222840-16842879-54960-3733-0000 on slave > 20150915-222840-16842879-54960-3733-S0 at slave(1)@127.0.1.1:54960 > (devstack007.cn.ibm.com) > I0915 22:28:41.836931 3758 master.cpp:3560] Processing ACKNOWLEDGE call > 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df for task 1 of framework > 20150915-222840-16842879-54960-3733-0000 (default) at > scheduler-a3a7c440-fbcb-496b-8934-ac7410bcbacc@127.0.1.1:54960 on slave > 20150915-222840-16842879-54960-3733-S0 > I0915 22:28:41.837369 3758 status_update_manager.cpp:394] Received status > update acknowledgement (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task > 1 of framework 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.837505 3758 status_update_manager.cpp:530] Cleaning up status > update stream for task 1 of framework 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.837813 3758 slave.cpp:2306] Status update manager > successfully handled status update acknowledgement (UUID: > 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of framework > 20150915-222840-16842879-54960-3733-0000 > E0915 22:28:41.837849 3758 slave.cpp:2317] Status update acknowledgement > (UUID: 6a8c03f0-509f-48e6-8fd5-ed7b47eb44df) for task 1 of unknown framework > 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.877821 3753 leveldb.cpp:343] Persisting action (18 bytes) to > leveldb took 41.327821ms > I0915 22:28:41.877909 3753 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 47279ns > I0915 22:28:41.877940 3753 replica.cpp:679] Persisted action at 4 > I0915 22:28:41.877981 3753 replica.cpp:664] Replica learned TRUNCATE action > at position 4 > I0915 22:28:41.906275 3754 process.cpp:3021] Handling HTTP event for process > 'metrics' with path: '/metrics/snapshot' > I0915 22:28:41.918052 3733 sched.cpp:1754] Asked to stop the driver > I0915 22:28:41.918167 3754 sched.cpp:1040] Stopping framework > '20150915-222840-16842879-54960-3733-0000' > I0915 22:28:41.918184 3752 master.cpp:921] Master terminating > I0915 22:28:41.918462 3755 hierarchical.hpp:643] Removed slave > 20150915-222840-16842879-54960-3733-S0 > I0915 22:28:41.918792 3755 hierarchical.hpp:490] Removed framework > 20150915-222840-16842879-54960-3733-0000 > I0915 22:28:41.919427 3756 slave.cpp:3151] master@127.0.1.1:54960 exited > W0915 22:28:41.919839 3756 slave.cpp:3154] Master disconnected! Waiting for > a new master to be elected > I0915 22:28:41.923146 3753 slave.cpp:572] Slave terminating > [ OK ] MasterSlaveReconciliationTest.ReconcileLostTask (1443 ms) > [----------] 1 test from MasterSlaveReconciliationTest (1443 ms total) > > [----------] Global test environment tear-down > [==========] 1 test from 1 test case ran. (1780 ms total) > [ PASSED ] 1 test. > make[3]: Leaving directory `/home/gyliu/src/mesos/bug-fix/mesos/build/src' > make[2]: Leaving directory `/home/gyliu/src/mesos/bug-fix/mesos/build/src' > make[1]: Leaving directory `/home/gyliu/src/mesos/bug-fix/mesos/build/src' > gyliu@devstack007: -- This message was sent by Atlassian JIRA (v6.3.4#6332)