[
https://issues.apache.org/jira/browse/MESOS-3422?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14745611#comment-14745611
]
Guangya Liu commented on MESOS-3422:
------------------------------------
[[email protected]] I'm sorry that I updated the problem description by
mistake, can you please help update the description again? Thanks!
> 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
> [email protected]: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
> [email protected]:54960
> I0915 22:28:41.620291 3752 sched.cpp:318] Authenticating with master
> [email protected]: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
> [email protected]: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
> [email protected]:54960
> I0915 22:28:41.621656 3758 slave.cpp:755] Authenticating with master
> [email protected]: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
> [email protected]: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 [email protected]:54960
> I0915 22:28:41.625535 3754 sched.cpp:714] Sending SUBSCRIBE call to
> [email protected]: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
> [email protected]:54960
> I0915 22:28:41.625833 3758 slave.cpp:823] Successfully authenticated with
> master [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]:54960
> I0915 22:28:41.822803 3758 slave.cpp:755] Authenticating with master
> [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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] [email protected]: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)
