You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Cody Maloney (JIRA)" <ji...@apache.org> on 2014/12/04 22:29:13 UTC
[jira] [Updated] (MESOS-2003) MasterTest.RecoverResources is flaky
[ https://issues.apache.org/jira/browse/MESOS-2003?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Cody Maloney updated MESOS-2003:
--------------------------------
Labels: flaky (was: )
> MasterTest.RecoverResources is flaky
> ------------------------------------
>
> Key: MESOS-2003
> URL: https://issues.apache.org/jira/browse/MESOS-2003
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.21.0
> Environment: https://builds.apache.org/computer/ubuntu-4/systemInfo
> Reporter: Yan Xu
> Labels: flaky
>
> {noformat:title=}
> [ RUN ] MasterTest.RecoverResources
> Using temporary directory '/tmp/MasterTest_RecoverResources_qqb0s0'
> I1028 02:38:04.489317 11875 leveldb.cpp:176] Opened db in 2.950284ms
> I1028 02:38:04.490468 11875 leveldb.cpp:183] Compacted db in 1.112309ms
> I1028 02:38:04.490506 11875 leveldb.cpp:198] Created db iterator in 6629ns
> I1028 02:38:04.490520 11875 leveldb.cpp:204] Seeked to beginning of db in 957ns
> I1028 02:38:04.490528 11875 leveldb.cpp:273] Iterated through 0 keys in the db in 445ns
> I1028 02:38:04.490573 11875 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1028 02:38:04.491502 11893 recover.cpp:437] Starting replica recovery
> I1028 02:38:04.491853 11893 recover.cpp:463] Replica is in EMPTY status
> I1028 02:38:04.493232 11892 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I1028 02:38:04.493645 11902 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I1028 02:38:04.494019 11904 recover.cpp:554] Updating replica status to STARTING
> I1028 02:38:04.494185 11890 master.cpp:312] Master 20141028-023804-3142697795-39931-11875 (pomona.apache.org) started on 67.195.81.187:39931
> I1028 02:38:04.494227 11890 master.cpp:358] Master only allowing authenticated frameworks to register
> I1028 02:38:04.494240 11890 master.cpp:363] Master only allowing authenticated slaves to register
> I1028 02:38:04.494288 11890 credentials.hpp:36] Loading credentials for authentication from '/tmp/MasterTest_RecoverResources_qqb0s0/credentials'
> I1028 02:38:04.494565 11890 master.cpp:392] Authorization enabled
> I1028 02:38:04.494784 11897 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 493006ns
> I1028 02:38:04.494801 11897 replica.cpp:320] Persisted replica status to STARTING
> I1028 02:38:04.494899 11898 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I1028 02:38:04.495121 11892 recover.cpp:463] Replica is in STARTING status
> I1028 02:38:04.495127 11889 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.187:39931
> I1028 02:38:04.495754 11890 master.cpp:1242] The newly elected leader is master@67.195.81.187:39931 with id 20141028-023804-3142697795-39931-11875
> I1028 02:38:04.495775 11890 master.cpp:1255] Elected as the leading master!
> I1028 02:38:04.495790 11890 master.cpp:1073] Recovering from registrar
> I1028 02:38:04.495888 11895 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I1028 02:38:04.495914 11894 registrar.cpp:313] Recovering registrar
> I1028 02:38:04.496381 11900 recover.cpp:188] Received a recover response from a replica in STARTING status
> I1028 02:38:04.496693 11904 recover.cpp:554] Updating replica status to VOTING
> I1028 02:38:04.497303 11896 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 483101ns
> I1028 02:38:04.497323 11896 replica.cpp:320] Persisted replica status to VOTING
> I1028 02:38:04.497421 11890 recover.cpp:568] Successfully joined the Paxos group
> I1028 02:38:04.497632 11890 recover.cpp:452] Recover process terminated
> I1028 02:38:04.497970 11892 log.cpp:656] Attempting to start the writer
> I1028 02:38:04.499183 11902 replica.cpp:474] Replica received implicit promise request with proposal 1
> I1028 02:38:04.499608 11902 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 398717ns
> I1028 02:38:04.499626 11902 replica.cpp:342] Persisted promised to 1
> I1028 02:38:04.500125 11904 coordinator.cpp:230] Coordinator attemping to fill missing position
> I1028 02:38:04.501308 11903 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I1028 02:38:04.501662 11903 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 322781ns
> I1028 02:38:04.501680 11903 replica.cpp:676] Persisted action at 0
> I1028 02:38:04.502385 11896 replica.cpp:508] Replica received write request for position 0
> I1028 02:38:04.502424 11896 leveldb.cpp:438] Reading position from leveldb took 19602ns
> I1028 02:38:04.502760 11896 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 309557ns
> I1028 02:38:04.502780 11896 replica.cpp:676] Persisted action at 0
> I1028 02:38:04.503149 11904 replica.cpp:655] Replica received learned notice for position 0
> I1028 02:38:04.503314 11904 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 144770ns
> I1028 02:38:04.503339 11904 replica.cpp:676] Persisted action at 0
> I1028 02:38:04.503362 11904 replica.cpp:661] Replica learned NOP action at position 0
> I1028 02:38:04.503749 11892 log.cpp:672] Writer started with ending position 0
> I1028 02:38:04.504786 11902 leveldb.cpp:438] Reading position from leveldb took 20835ns
> I1028 02:38:04.507366 11898 registrar.cpp:346] Successfully fetched the registry (0B) in 11.42016ms
> I1028 02:38:04.507504 11898 registrar.cpp:445] Applied 1 operations in 37651ns; attempting to update the 'registry'
> I1028 02:38:04.510162 11893 log.cpp:680] Attempting to append 139 bytes to the log
> I1028 02:38:04.510406 11889 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I1028 02:38:04.511181 11889 replica.cpp:508] Replica received write request for position 1
> I1028 02:38:04.511767 11889 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 550337ns
> I1028 02:38:04.511792 11889 replica.cpp:676] Persisted action at 1
> I1028 02:38:04.512370 11889 replica.cpp:655] Replica received learned notice for position 1
> I1028 02:38:04.512802 11889 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 411874ns
> I1028 02:38:04.512821 11889 replica.cpp:676] Persisted action at 1
> I1028 02:38:04.512841 11889 replica.cpp:661] Replica learned APPEND action at position 1
> I1028 02:38:04.513649 11895 registrar.cpp:490] Successfully updated the 'registry' in 6.086144ms
> I1028 02:38:04.513772 11895 registrar.cpp:376] Successfully recovered registrar
> I1028 02:38:04.513991 11891 log.cpp:699] Attempting to truncate the log to 1
> I1028 02:38:04.514045 11895 master.cpp:1100] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register
> I1028 02:38:04.514138 11889 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I1028 02:38:04.514847 11898 replica.cpp:508] Replica received write request for position 2
> I1028 02:38:04.515223 11898 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 349767ns
> I1028 02:38:04.515239 11898 replica.cpp:676] Persisted action at 2
> I1028 02:38:04.515666 11898 replica.cpp:655] Replica received learned notice for position 2
> I1028 02:38:04.516059 11898 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 377837ns
> I1028 02:38:04.516091 11898 leveldb.cpp:401] Deleting ~1 keys from leveldb took 16661ns
> I1028 02:38:04.516103 11898 replica.cpp:676] Persisted action at 2
> I1028 02:38:04.516118 11898 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I1028 02:38:04.528028 11893 slave.cpp:169] Slave started on 28)@67.195.81.187:39931
> I1028 02:38:04.528062 11893 credentials.hpp:84] Loading credential for authentication from '/tmp/MasterTest_RecoverResources_vPPbEB/credential'
> I1028 02:38:04.528213 11893 slave.cpp:276] Slave using credential for: test-principal
> I1028 02:38:04.528563 11893 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30]
> I1028 02:38:04.528663 11893 slave.cpp:318] Slave hostname: pomona.apache.org
> I1028 02:38:04.528677 11893 slave.cpp:319] Slave checkpoint: false
> W1028 02:38:04.528684 11893 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
> I1028 02:38:04.529392 11892 state.cpp:33] Recovering state from '/tmp/MasterTest_RecoverResources_vPPbEB/meta'
> I1028 02:38:04.532413 11875 sched.cpp:137] Version: 0.21.0
> I1028 02:38:05.495925 11903 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I1028 02:38:09.495995 11899 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I1028 02:38:13.648022 11903 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 8.152112733secs
> I1028 02:38:13.648339 11903 status_update_manager.cpp:197] Recovering status update manager
> I1028 02:38:13.648790 11903 sched.cpp:233] New master detected at master@67.195.81.187:39931
> I1028 02:38:13.648816 11903 sched.cpp:283] Authenticating with master master@67.195.81.187:39931
> I1028 02:38:13.648828 11900 slave.cpp:3456] Finished recovery
> I1028 02:38:13.649049 11894 authenticatee.hpp:133] Creating new client SASL connection
> I1028 02:38:13.649325 11901 master.cpp:3853] Authenticating scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:13.649443 11893 status_update_manager.cpp:171] Pausing sending status updates
> I1028 02:38:13.649458 11896 slave.cpp:602] New master detected at master@67.195.81.187:39931
> I1028 02:38:13.649487 11896 slave.cpp:665] Authenticating with master master@67.195.81.187:39931
> I1028 02:38:13.649515 11894 authenticator.hpp:161] Creating new server SASL connection
> I1028 02:38:13.649595 11896 slave.cpp:638] Detecting new master
> I1028 02:38:13.649634 11897 authenticatee.hpp:133] Creating new client SASL connection
> I1028 02:38:13.649688 11898 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
> I1028 02:38:13.649723 11898 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1028 02:38:13.649793 11903 master.cpp:3853] Authenticating slave(28)@67.195.81.187:39931
> I1028 02:38:13.649809 11896 authenticator.hpp:267] Received SASL authentication start
> I1028 02:38:13.649863 11896 authenticator.hpp:389] Authentication requires more steps
> I1028 02:38:13.649957 11900 authenticatee.hpp:270] Received SASL authentication step
> I1028 02:38:13.649961 11898 authenticator.hpp:161] Creating new server SASL connection
> I1028 02:38:13.650054 11900 authenticator.hpp:295] Received SASL authentication step
> I1028 02:38:13.650084 11900 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1028 02:38:13.650100 11900 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I1028 02:38:13.650142 11897 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
> I1028 02:38:13.650187 11897 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1028 02:38:13.650151 11900 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1028 02:38:13.650265 11900 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1028 02:38:13.650357 11900 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1028 02:38:13.650364 11900 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1028 02:38:13.650387 11900 authenticator.hpp:381] Authentication success
> I1028 02:38:13.650293 11897 authenticator.hpp:267] Received SASL authentication start
> I1028 02:38:13.650456 11897 authenticator.hpp:389] Authentication requires more steps
> I1028 02:38:13.650511 11898 authenticatee.hpp:310] Authentication success
> I1028 02:38:13.650609 11904 authenticatee.hpp:270] Received SASL authentication step
> I1028 02:38:13.650616 11900 master.cpp:3893] Successfully authenticated principal 'test-principal' at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:13.650682 11904 authenticator.hpp:295] Received SASL authentication step
> I1028 02:38:13.650714 11904 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1028 02:38:13.650732 11904 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I1028 02:38:13.650774 11904 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1028 02:38:13.650805 11904 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1028 02:38:13.650820 11904 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1028 02:38:13.650831 11904 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1028 02:38:13.650851 11904 authenticator.hpp:381] Authentication success
> I1028 02:38:13.650931 11894 authenticatee.hpp:310] Authentication success
> I1028 02:38:13.650926 11896 sched.cpp:357] Successfully authenticated with master master@67.195.81.187:39931
> I1028 02:38:13.650966 11896 sched.cpp:476] Sending registration request to master@67.195.81.187:39931
> I1028 02:38:13.650967 11899 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(28)@67.195.81.187:39931
> I1028 02:38:13.651166 11897 slave.cpp:722] Successfully authenticated with master master@67.195.81.187:39931
> I1028 02:38:13.651206 11899 master.cpp:1362] Received registration request for framework 'default' at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:13.651298 11899 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I1028 02:38:13.651316 11897 slave.cpp:1050] Will retry registration in 1.610177ms if necessary
> I1028 02:38:13.651870 11899 master.cpp:3032] Registering slave at slave(28)@67.195.81.187:39931 (pomona.apache.org) with id 20141028-023804-3142697795-39931-11875-S0
> I1028 02:38:13.652227 11899 master.cpp:1426] Registering framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:13.652349 11904 registrar.cpp:445] Applied 1 operations in 87188ns; attempting to update the 'registry'
> I1028 02:38:13.652542 11891 hierarchical_allocator_process.hpp:329] Added framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:13.652564 11891 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I1028 02:38:13.652572 11891 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 13012ns
> I1028 02:38:13.652673 11892 sched.cpp:407] Framework registered with 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:13.652714 11892 sched.cpp:421] Scheduler::registered took 20560ns
> I1028 02:38:13.653688 11891 slave.cpp:1050] Will retry registration in 26.064716ms if necessary
> I1028 02:38:13.653826 11889 master.cpp:3020] Ignoring register slave message from slave(28)@67.195.81.187:39931 (pomona.apache.org) as admission is already in progress
> I1028 02:38:13.655606 11902 log.cpp:680] Attempting to append 318 bytes to the log
> I1028 02:38:13.655783 11891 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I1028 02:38:13.656572 11889 replica.cpp:508] Replica received write request for position 3
> I1028 02:38:13.656903 11889 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 297428ns
> I1028 02:38:13.656929 11889 replica.cpp:676] Persisted action at 3
> I1028 02:38:13.657467 11899 replica.cpp:655] Replica received learned notice for position 3
> I1028 02:38:13.658213 11899 leveldb.cpp:343] Persisting action (339 bytes) to leveldb took 720488ns
> I1028 02:38:13.658237 11899 replica.cpp:676] Persisted action at 3
> I1028 02:38:13.658262 11899 replica.cpp:661] Replica learned APPEND action at position 3
> I1028 02:38:13.680084 11897 slave.cpp:1050] Will retry registration in 64.496922ms if necessary
> I1028 02:38:13.680219 11904 master.cpp:3020] Ignoring register slave message from slave(28)@67.195.81.187:39931 (pomona.apache.org) as admission is already in progress
> I1028 02:38:14.648702 11898 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I1028 02:38:18.649222 11895 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I1028 02:38:19.073879 11898 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 4.425188279secs
> I1028 02:38:19.075243 11901 registrar.cpp:490] Successfully updated the 'registry' in 5.422822144secs
> I1028 02:38:19.075714 11899 log.cpp:699] Attempting to truncate the log to 3
> I1028 02:38:19.075899 11898 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I1028 02:38:19.076500 11897 master.cpp:3086] Registered slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30]
> I1028 02:38:19.076617 11890 slave.cpp:2522] Received ping from slave-observer(30)@67.195.81.187:39931
> I1028 02:38:19.076676 11896 hierarchical_allocator_process.hpp:442] Added slave 20141028-023804-3142697795-39931-11875-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30] available)
> I1028 02:38:19.076746 11890 slave.cpp:756] Registered with master master@67.195.81.187:39931; given slave ID 20141028-023804-3142697795-39931-11875-S0
> I1028 02:38:19.076867 11892 status_update_manager.cpp:178] Resuming sending status updates
> I1028 02:38:19.076930 11896 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[1-10, 20-30] on slave 20141028-023804-3142697795-39931-11875-S0 to framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.077153 11895 replica.cpp:508] Replica received write request for position 4
> I1028 02:38:19.077503 11896 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141028-023804-3142697795-39931-11875-S0 in 739782ns
> I1028 02:38:19.077662 11895 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 477107ns
> I1028 02:38:19.077687 11895 replica.cpp:676] Persisted action at 4
> I1028 02:38:19.077909 11904 master.cpp:3795] Sending 1 offers to framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:19.078209 11889 replica.cpp:655] Replica received learned notice for position 4
> I1028 02:38:19.078366 11890 sched.cpp:544] Scheduler::resourceOffers took 83920ns
> I1028 02:38:19.078709 11889 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 477172ns
> I1028 02:38:19.078771 11889 leveldb.cpp:401] Deleting ~2 keys from leveldb took 38131ns
> I1028 02:38:19.078789 11889 replica.cpp:676] Persisted action at 4
> I1028 02:38:19.078812 11889 replica.cpp:661] Replica learned TRUNCATE action at position 4
> I1028 02:38:19.080180 11895 master.cpp:2321] Processing reply for offers: [ 20141028-023804-3142697795-39931-11875-O0 ] on slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org) for framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:19.080445 11895 master.cpp:2417] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
> I1028 02:38:19.081792 11895 master.hpp:877] Adding task 1 with resources cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30] on slave 20141028-023804-3142697795-39931-11875-S0 (pomona.apache.org)
> I1028 02:38:19.081954 11895 master.cpp:2480] Launching task 1 of framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 with resources cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30] on slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org)
> I1028 02:38:19.082350 11897 slave.cpp:1081] Got assigned task 1 for framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.083044 11897 slave.cpp:1191] Launching task 1 for framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.085844 11897 slave.cpp:3871] Launching executor default of framework 20141028-023804-3142697795-39931-11875-0000 in work directory '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default/runs/b2955790-a58e-4fba-bc7f-2e851c9b88d7'
> I1028 02:38:19.088114 11897 exec.cpp:132] Version: 0.21.0
> I1028 02:38:19.088326 11889 exec.cpp:182] Executor started at: executor(11)@67.195.81.187:39931 with pid 11875
> I1028 02:38:19.088418 11897 slave.cpp:1317] Queuing task '1' for executor default of framework '20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.088522 11897 slave.cpp:555] Successfully attached file '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default/runs/b2955790-a58e-4fba-bc7f-2e851c9b88d7'
> I1028 02:38:19.088574 11897 slave.cpp:1849] Got registration for executor 'default' of framework 20141028-023804-3142697795-39931-11875-0000 from executor(11)@67.195.81.187:39931
> I1028 02:38:19.088897 11897 slave.cpp:1968] Flushing queued task 1 for executor 'default' of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.088979 11893 exec.cpp:206] Executor registered on slave 20141028-023804-3142697795-39931-11875-S0
> I1028 02:38:19.089085 11897 slave.cpp:2802] Monitoring executor 'default' of framework '20141028-023804-3142697795-39931-11875-0000' in container 'b2955790-a58e-4fba-bc7f-2e851c9b88d7'
> I1028 02:38:19.090515 11893 exec.cpp:218] Executor::registered took 28546ns
> I1028 02:38:19.090698 11893 exec.cpp:293] Executor asked to run task '1'
> I1028 02:38:19.090760 11893 exec.cpp:302] Executor::launchTask took 44937ns
> I1028 02:38:19.093014 11893 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.093221 11893 slave.cpp:2202] Handling status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 from executor(11)@67.195.81.187:39931
> I1028 02:38:19.093544 11896 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.093583 11896 status_update_manager.cpp:494] Creating StatusUpdate stream for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.093793 11896 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to the slave
> I1028 02:38:19.093969 11889 slave.cpp:2442] Forwarding the update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to master@67.195.81.187:39931
> I1028 02:38:19.094104 11889 slave.cpp:2369] Status update manager successfully handled status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:19.094131 11889 slave.cpp:2375] Sending acknowledgement for status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to executor(11)@67.195.81.187:39931
> I1028 02:38:19.094238 11890 master.cpp:3410] Forwarding status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:20.075256 11899 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 158229ns
> I1028 02:38:22.352753 11889 exec.cpp:339] Executor received status update acknowledgement c1c3fead-3939-4a31-a474-58c5e3078c80 for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.352778 11890 master.cpp:3382] Status update TASK_RUNNING (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 from slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org)
> I1028 02:38:22.352833 11890 master.cpp:4617] Updating the latest state of task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to TASK_RUNNING
> I1028 02:38:22.352912 11900 sched.cpp:635] Scheduler::statusUpdate took 52537ns
> I1028 02:38:22.353186 11894 master.cpp:2882] Forwarding status update acknowledgement c1c3fead-3939-4a31-a474-58c5e3078c80 for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 to slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org)
> I1028 02:38:22.353481 11894 master.cpp:2683] Asked to kill task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.353530 11891 status_update_manager.cpp:389] Received status update acknowledgement (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.353579 11894 master.cpp:2778] Telling slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org) to kill task 1 of framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:22.353713 11898 slave.cpp:1373] Asked to kill task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.353994 11898 slave.cpp:1789] Status update manager successfully handled status update acknowledgement (UUID: c1c3fead-3939-4a31-a474-58c5e3078c80) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.354019 11894 exec.cpp:313] Executor asked to kill task '1'
> I1028 02:38:22.354121 11894 exec.cpp:322] Executor::killTask took 77148ns
> I1028 02:38:22.356482 11894 exec.cpp:525] Executor sending status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.356678 11889 slave.cpp:2202] Handling status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 from executor(11)@67.195.81.187:39931
> I1028 02:38:22.356757 11889 slave.cpp:4179] Terminating task 1
> I1028 02:38:22.357367 11894 status_update_manager.cpp:317] Received status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.357496 11894 status_update_manager.cpp:371] Forwarding update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to the slave
> I1028 02:38:22.357637 11890 slave.cpp:2442] Forwarding the update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to master@67.195.81.187:39931
> I1028 02:38:22.357755 11890 slave.cpp:2369] Status update manager successfully handled status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.357785 11890 slave.cpp:2375] Sending acknowledgement for status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to executor(11)@67.195.81.187:39931
> I1028 02:38:22.357969 11904 exec.cpp:339] Executor received status update acknowledgement cb28dd88-bdb0-4d16-b4bc-977fcf018b2f for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.357972 11899 master.cpp:3410] Forwarding status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.358099 11899 master.cpp:3382] Status update TASK_KILLED (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 from slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org)
> I1028 02:38:22.358144 11899 master.cpp:4617] Updating the latest state of task 1 of framework 20141028-023804-3142697795-39931-11875-0000 to TASK_KILLED
> I1028 02:38:22.358268 11890 sched.cpp:635] Scheduler::statusUpdate took 60378ns
> I1028 02:38:22.358825 11893 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30] (total allocatable: cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30]) on slave 20141028-023804-3142697795-39931-11875-S0 from framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.358850 11899 master.cpp:4676] Removing task 1 with resources cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30] of framework 20141028-023804-3142697795-39931-11875-0000 on slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org)
> I1028 02:38:22.358989 11899 master.cpp:2882] Forwarding status update acknowledgement cb28dd88-bdb0-4d16-b4bc-977fcf018b2f for task 1 of framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 to slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org)
> I1028 02:38:22.359190 11899 master.cpp:2671] Reviving offers for framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:22.359256 11896 status_update_manager.cpp:389] Received status update acknowledgement (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.359347 11896 status_update_manager.cpp:525] Cleaning up status update stream for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.359354 11900 hierarchical_allocator_process.hpp:632] Removed filters for framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.359622 11890 slave.cpp:1789] Status update manager successfully handled status update acknowledgement (UUID: cb28dd88-bdb0-4d16-b4bc-977fcf018b2f) for task 1 of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.359602 11900 hierarchical_allocator_process.hpp:734] Offering cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30] on slave 20141028-023804-3142697795-39931-11875-S0 to framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:22.359665 11890 slave.cpp:4218] Completing task 1
> I1028 02:38:22.360123 11900 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 732112ns
> I1028 02:38:22.360455 11903 master.cpp:3795] Sending 1 offers to framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:22.360826 11896 sched.cpp:544] Scheduler::resourceOffers took 61664ns
> I1028 02:38:22.361403 11903 slave.cpp:2860] Executor 'default' of framework 20141028-023804-3142697795-39931-11875-0000 exited with status 0
> I1028 02:38:22.361948 11900 master.cpp:2321] Processing reply for offers: [ 20141028-023804-3142697795-39931-11875-O1 ] on slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org) for framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:23.353077 11893 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 168599ns
> I1028 02:38:24.074503 11899 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I1028 02:38:31.522539 11903 slave.cpp:2997] Cleaning up executor 'default' of framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:31.522729 11904 gc.cpp:56] Scheduling '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default/runs/b2955790-a58e-4fba-bc7f-2e851c9b88d7' for gc 6.99999395104296days in the future
> I1028 02:38:31.522784 11903 slave.cpp:3074] Cleaning up framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:31.522855 11899 status_update_manager.cpp:279] Closing status update streams for framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:31.522948 11904 gc.cpp:56] Scheduling '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000/executors/default' for gc 6.99999394972148days in the future
> I1028 02:38:31.522985 11900 master.cpp:3462] Executor default of framework 20141028-023804-3142697795-39931-11875-0000 on slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org) exited with status 0
> I1028 02:38:31.523069 11904 gc.cpp:56] Scheduling '/tmp/MasterTest_RecoverResources_vPPbEB/slaves/20141028-023804-3142697795-39931-11875-S0/frameworks/20141028-023804-3142697795-39931-11875-0000' for gc 6.99999394800889days in the future
> I1028 02:38:31.523079 11900 master.cpp:4705] Removing executor 'default' with resources cpus(*):0.3; mem(*):200; ports(*):[5-8, 23-25] of framework 20141028-023804-3142697795-39931-11875-0000 on slave 20141028-023804-3142697795-39931-11875-S0 at slave(28)@67.195.81.187:39931 (pomona.apache.org)
> I1028 02:38:31.523833 11901 hierarchical_allocator_process.hpp:563] Recovered cpus(*):0.3; mem(*):200; ports(*):[5-8, 23-25] (total allocatable: cpus(*):0.3; mem(*):200; ports(*):[5-8, 23-25]) on slave 20141028-023804-3142697795-39931-11875-S0 from framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:31.524312 11901 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1.7; mem(*):824; disk(*):1024; ports(*):[1-4, 9-10, 20-22, 26-30] (total allocatable: cpus(*):2; mem(*):1024; ports(*):[1-10, 20-30]; disk(*):1024) on slave 20141028-023804-3142697795-39931-11875-S0 from framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:31.524363 11901 hierarchical_allocator_process.hpp:599] Framework 20141028-023804-3142697795-39931-11875-0000 filtered slave 20141028-023804-3142697795-39931-11875-S0 for 5secs
> tests/master_tests.cpp:743: Failure
> Failed to wait 10secs for offers
> I1028 02:38:32.363447 11896 master.cpp:768] Framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 disconnected
> I1028 02:38:32.363498 11896 master.cpp:1731] Disconnecting framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:32.363535 11896 master.cpp:1747] Deactivating framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:32.363697 11896 master.cpp:790] Giving framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931 0ns to failover
> I1028 02:38:32.363828 11899 hierarchical_allocator_process.hpp:405] Deactivated framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:32.363980 11898 master.cpp:3665] Framework failover timeout, removing framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> I1028 02:38:32.364006 11898 master.cpp:4201] Removing framework 20141028-023804-3142697795-39931-11875-0000 (default) at scheduler-fa6faf5c-dace-42f2-a5ab-d32295e6006e@67.195.81.187:39931
> tests/master_tests.cpp:729: Failure
> Actual function call count doesn't match EXPECT_CALL(sched, resourceOffers(&driver, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> I1028 02:38:32.364336 11889 slave.cpp:1522] Asked to shut down framework 20141028-023804-3142697795-39931-11875-0000 by master@67.195.81.187:39931
> W1028 02:38:32.364373 11889 slave.cpp:1537] Cannot shut down unknown framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:32.364612 11898 hierarchical_allocator_process.hpp:360] Removed framework 20141028-023804-3142697795-39931-11875-0000
> I1028 02:38:32.364822 11875 master.cpp:677] Master terminating
> I1028 02:38:32.365265 11899 slave.cpp:2607] master@67.195.81.187:39931 exited
> W1028 02:38:32.365299 11899 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
> *** Aborted at 1414463912 (unix time) try "date -d @1414463912" if you are using GNU date ***
> PC: @ 0x1c52008 (unknown)
> *** SIGSEGV (@0x1c52008) received by PID 11875 (TID 0x2ad3bf0f6100) from PID 29696008; stack trace: ***
> @ 0x2ad3c917685a call_chained_handler()
> @ 0x2ad3c9173deb os::Linux::chained_handler()
> @ 0x2ad3c9177420 JVM_handle_linux_signal
> @ 0x2ad3c9173cfe signalHandler()
> @ 0x2ad3c43be340 (unknown)
> @ 0x1c52008 (unknown)
> make[3]: *** [check-local] Segmentation fault
> make[3]: Leaving directory `/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src'
> make[2]: *** [check-am] Error 2
> make[2]: Leaving directory `/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src'
> make[1]: *** [check] Error 2
> make[1]: Leaving directory `/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src'
> make: *** [check-recursive] Error 1
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)