mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dominic Hamon (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (MESOS-1553) MasterTest.KillTask is flaky
Date Tue, 01 Jul 2014 22:27:25 GMT

     [ https://issues.apache.org/jira/browse/MESOS-1553?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Dominic Hamon updated MESOS-1553:
---------------------------------

    Assignee:     (was: Dominic Hamon)

> MasterTest.KillTask is flaky
> ----------------------------
>
>                 Key: MESOS-1553
>                 URL: https://issues.apache.org/jira/browse/MESOS-1553
>             Project: Mesos
>          Issue Type: Bug
>          Components: test
>            Reporter: Vinod Kone
>
> Not entirely sure if this is the fault of the test. It looks like Cluster::Slaves::shutdown()
was never called presumable because Cluster::Master::shutdown() was blocked on something.
> {code}
> [ RUN      ] MasterTest.KillTask
> Using temporary directory '/tmp/MasterTest_KillTask_BYKYwN'
> I0627 13:11:56.627650  6574 leveldb.cpp:176] Opened db in 706544ns
> I0627 13:11:56.628262  6574 leveldb.cpp:183] Compacted db in 234376ns
> I0627 13:11:56.628664  6574 leveldb.cpp:198] Created db iterator in 6515ns
> I0627 13:11:56.628991  6574 leveldb.cpp:204] Seeked to beginning of db in 1589ns
> I0627 13:11:56.629302  6574 leveldb.cpp:273] Iterated through 0 keys in the db in 837ns
> I0627 13:11:56.629667  6574 replica.cpp:741] Replica recovered with log positions 0 ->
0 with 1 holes and 0 unlearned
> I0627 13:11:56.630141  6594 recover.cpp:425] Starting replica recovery
> I0627 13:11:56.630204  6594 recover.cpp:451] Replica is in EMPTY status
> I0627 13:11:56.630439  6594 replica.cpp:638] Replica in EMPTY status received a broadcasted
recover request
> I0627 13:11:56.630491  6594 recover.cpp:188] Received a recover response from a replica
in EMPTY status
> I0627 13:11:56.630604  6594 recover.cpp:542] Updating replica status to STARTING
> I0627 13:11:56.630693  6594 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb
took 40601ns
> I0627 13:11:56.630708  6594 replica.cpp:320] Persisted replica status to STARTING
> I0627 13:11:56.630744  6594 recover.cpp:451] Replica is in STARTING status
> I0627 13:11:56.630914  6594 replica.cpp:638] Replica in STARTING status received a broadcasted
recover request
> I0627 13:11:56.630955  6594 recover.cpp:188] Received a recover response from a replica
in STARTING status
> I0627 13:11:56.631019  6594 recover.cpp:542] Updating replica status to VOTING
> I0627 13:11:56.631067  6594 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb
took 15771ns
> I0627 13:11:56.631080  6594 replica.cpp:320] Persisted replica status to VOTING
> I0627 13:11:56.631100  6594 recover.cpp:556] Successfully joined the Paxos group
> I0627 13:11:56.631136  6594 recover.cpp:440] Recover process terminated
> I0627 13:11:56.634690  6600 master.cpp:288] Master 20140627-131156-2759502016-44870-6574
(fedora-20) started on 192.168.122.164:44870
> I0627 13:11:56.634718  6600 master.cpp:325] Master only allowing authenticated frameworks
to register
> I0627 13:11:56.634726  6600 master.cpp:330] Master only allowing authenticated slaves
to register
> I0627 13:11:56.634733  6600 credentials.hpp:35] Loading credentials for authentication
from '/tmp/MasterTest_KillTask_BYKYwN/credentials'
> I0627 13:11:56.634809  6600 master.cpp:356] Authorization enabled
> I0627 13:11:56.635213  6600 hierarchical_allocator_process.hpp:301] Initializing hierarchical
allocator process with master : master@192.168.122.164:44870
> I0627 13:11:56.635254  6600 master.cpp:122] No whitelist given. Advertising offers for
all slaves
> I0627 13:11:56.635414  6600 master.cpp:1122] The newly elected leader is master@192.168.122.164:44870
with id 20140627-131156-2759502016-44870-6574
> I0627 13:11:56.635431  6600 master.cpp:1135] Elected as the leading master!
> I0627 13:11:56.635437  6600 master.cpp:953] Recovering from registrar
> I0627 13:11:56.635483  6600 registrar.cpp:313] Recovering registrar
> I0627 13:11:56.635711  6596 log.cpp:656] Attempting to start the writer
> I0627 13:11:56.635979  6596 replica.cpp:474] Replica received implicit promise request
with proposal 1
> I0627 13:11:56.636018  6596 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb
took 20426ns
> I0627 13:11:56.636029  6596 replica.cpp:342] Persisted promised to 1
> I0627 13:11:56.636169  6596 coordinator.cpp:230] Coordinator attemping to fill missing
position
> I0627 13:11:56.636431  6596 replica.cpp:375] Replica received explicit promise request
for position 0 with proposal 2
> I0627 13:11:56.636467  6596 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took
18333ns
> I0627 13:11:56.636478  6596 replica.cpp:676] Persisted action at 0
> I0627 13:11:56.636855  6598 replica.cpp:508] Replica received write request for position
0
> I0627 13:11:56.636889  6598 leveldb.cpp:438] Reading position from leveldb took 14464ns
> I0627 13:11:56.636916  6598 leveldb.cpp:343] Persisting action (14 bytes) to leveldb
took 12858ns
> I0627 13:11:56.636926  6598 replica.cpp:676] Persisted action at 0
> I0627 13:11:56.637024  6598 replica.cpp:655] Replica received learned notice for position
0
> I0627 13:11:56.637053  6598 leveldb.cpp:343] Persisting action (16 bytes) to leveldb
took 13374ns
> I0627 13:11:56.637061  6598 replica.cpp:676] Persisted action at 0
> I0627 13:11:56.637069  6598 replica.cpp:661] Replica learned NOP action at position 0
> I0627 13:11:56.637204  6598 log.cpp:672] Writer started with ending position 0
> I0627 13:11:56.637421  6598 leveldb.cpp:438] Reading position from leveldb took 11368ns
> I0627 13:11:56.638617  6600 registrar.cpp:346] Successfully fetched the registry (0B)
> I0627 13:11:56.638644  6600 registrar.cpp:422] Attempting to update the 'registry'
> I0627 13:11:56.639808  6596 log.cpp:680] Attempting to append 130 bytes to the log
> I0627 13:11:56.639859  6596 coordinator.cpp:340] Coordinator attempting to write APPEND
action at position 1
> I0627 13:11:56.640022  6596 replica.cpp:508] Replica received write request for position
1
> I0627 13:11:56.640058  6596 leveldb.cpp:343] Persisting action (149 bytes) to leveldb
took 19174ns
> I0627 13:11:56.640069  6596 replica.cpp:676] Persisted action at 1
> I0627 13:11:56.640214  6596 replica.cpp:655] Replica received learned notice for position
1
> I0627 13:11:56.640246  6596 leveldb.cpp:343] Persisting action (151 bytes) to leveldb
took 15820ns
> I0627 13:11:56.640257  6596 replica.cpp:676] Persisted action at 1
> I0627 13:11:56.640265  6596 replica.cpp:661] Replica learned APPEND action at position
1
> I0627 13:11:56.640719  6600 registrar.cpp:479] Successfully updated 'registry'
> I0627 13:11:56.640883  6597 log.cpp:699] Attempting to truncate the log to 1
> I0627 13:11:56.641088  6597 coordinator.cpp:340] Coordinator attempting to write TRUNCATE
action at position 2
> I0627 13:11:56.641263  6597 replica.cpp:508] Replica received write request for position
2
> I0627 13:11:56.641298  6597 leveldb.cpp:343] Persisting action (16 bytes) to leveldb
took 16731ns
> I0627 13:11:56.641309  6597 replica.cpp:676] Persisted action at 2
> I0627 13:11:56.641448  6597 replica.cpp:655] Replica received learned notice for position
2
> I0627 13:11:56.641477  6597 leveldb.cpp:343] Persisting action (18 bytes) to leveldb
took 15029ns
> I0627 13:11:56.641494  6597 leveldb.cpp:401] Deleting ~1 keys from leveldb took 5454ns
> I0627 13:11:56.641501  6597 replica.cpp:676] Persisted action at 2
> I0627 13:11:56.641510  6597 replica.cpp:661] Replica learned TRUNCATE action at position
2
> I0627 13:11:56.642482  6600 registrar.cpp:372] Successfully recovered registrar
> I0627 13:11:56.643059  6599 master.cpp:980] Recovered 0 slaves from the Registry (94B)
; allowing 10mins for slaves to re-register
> I0627 13:11:56.646581  6596 slave.cpp:168] Slave started on 34)@192.168.122.164:44870
> I0627 13:11:56.646605  6596 credentials.hpp:35] Loading credentials for authentication
from '/tmp/MasterTest_KillTask_1QXLT0/credential'
> I0627 13:11:56.646672  6596 slave.cpp:268] Slave using credential for: test-principal
> I0627 13:11:56.646762  6596 slave.cpp:281] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
> I0627 13:11:56.646785  6596 slave.cpp:293] Slave private resources: 
> I0627 13:11:56.647164  6596 slave.cpp:326] Slave hostname: fedora-20
> I0627 13:11:56.647183  6596 slave.cpp:327] Slave checkpoint: false
> I0627 13:11:56.647807  6596 state.cpp:33] Recovering state from '/tmp/MasterTest_KillTask_1QXLT0/meta'
> I0627 13:11:56.647929  6596 status_update_manager.cpp:193] Recovering status update manager
> I0627 13:11:56.648002  6596 slave.cpp:3128] Finished recovery
> I0627 13:11:56.648267  6596 slave.cpp:601] New master detected at master@192.168.122.164:44870
> I0627 13:11:56.648294  6596 slave.cpp:677] Authenticating with master master@192.168.122.164:44870
> I0627 13:11:56.648334  6596 slave.cpp:650] Detecting new master
> I0627 13:11:56.648366  6596 status_update_manager.cpp:167] New master detected at master@192.168.122.164:44870
> I0627 13:11:56.648401  6596 authenticatee.hpp:128] Creating new client SASL connection
> I0627 13:11:56.648946  6599 master.cpp:3499] Authenticating slave(34)@192.168.122.164:44870
> I0627 13:11:56.649042  6599 authenticator.hpp:156] Creating new server SASL connection
> I0627 13:11:56.649513  6596 authenticatee.hpp:219] Received SASL authentication mechanisms:
CRAM-MD5
> I0627 13:11:56.649894  6596 authenticatee.hpp:245] Attempting to authenticate with mechanism
'CRAM-MD5'
> I0627 13:11:56.650305  6600 authenticator.hpp:262] Received SASL authentication start
> I0627 13:11:56.650353  6600 authenticator.hpp:384] Authentication requires more steps
> I0627 13:11:56.650591  6596 authenticatee.hpp:265] Received SASL authentication step
> I0627 13:11:56.651026  6594 authenticator.hpp:290] Received SASL authentication step
> I0627 13:11:56.651052  6594 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: false 
> I0627 13:11:56.651062  6594 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0627 13:11:56.651072  6594 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0627 13:11:56.651083  6594 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: true 
> I0627 13:11:56.651090  6594 auxprop.cpp:103] Skipping auxiliary property '*userPassword'
since SASL_AUXPROP_AUTHZID == true
> I0627 13:11:56.651095  6594 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5'
since SASL_AUXPROP_AUTHZID == true
> I0627 13:11:56.651108  6594 authenticator.hpp:376] Authentication success
> I0627 13:11:56.651144  6594 master.cpp:3539] Successfully authenticated principal 'test-principal'
at slave(34)@192.168.122.164:44870
> I0627 13:11:56.654723  6596 authenticatee.hpp:305] Authentication success
> I0627 13:11:56.656740  6598 slave.cpp:734] Successfully authenticated with master master@192.168.122.164:44870
> I0627 13:11:56.656986  6598 slave.cpp:972] Will retry registration in 518267ns if necessary
> I0627 13:11:56.657619  6594 master.cpp:2781] Registering slave at slave(34)@192.168.122.164:44870
(fedora-20) with id 20140627-131156-2759502016-44870-6574-0
> I0627 13:11:56.658327  6599 registrar.cpp:422] Attempting to update the 'registry'
> I0627 13:11:56.659365  6599 log.cpp:680] Attempting to append 310 bytes to the log
> I0627 13:11:56.659420  6599 coordinator.cpp:340] Coordinator attempting to write APPEND
action at position 3
> I0627 13:11:56.659651  6600 slave.cpp:972] Will retry registration in 14.165896ms if
necessary
> I0627 13:11:56.660229  6593 replica.cpp:508] Replica received write request for position
3
> I0627 13:11:56.660296  6593 leveldb.cpp:343] Persisting action (329 bytes) to leveldb
took 41312ns
> I0627 13:11:56.660310  6593 replica.cpp:676] Persisted action at 3
> I0627 13:11:56.660866  6595 replica.cpp:655] Replica received learned notice for position
3
> I0627 13:11:56.660907  6595 leveldb.cpp:343] Persisting action (331 bytes) to leveldb
took 19133ns
> I0627 13:11:56.660919  6595 replica.cpp:676] Persisted action at 3
> I0627 13:11:56.660928  6595 replica.cpp:661] Replica learned APPEND action at position
3
> I0627 13:11:56.664384  6593 registrar.cpp:479] Successfully updated 'registry'
> I0627 13:11:56.664872  6600 log.cpp:699] Attempting to truncate the log to 3
> I0627 13:11:56.664921  6600 coordinator.cpp:340] Coordinator attempting to write TRUNCATE
action at position 4
> I0627 13:11:56.665186  6600 replica.cpp:508] Replica received write request for position
4
> I0627 13:11:56.665226  6600 leveldb.cpp:343] Persisting action (16 bytes) to leveldb
took 19826ns
> I0627 13:11:56.665237  6600 replica.cpp:676] Persisted action at 4
> I0627 13:11:56.665379  6600 replica.cpp:655] Replica received learned notice for position
4
> I0627 13:11:56.665408  6600 leveldb.cpp:343] Persisting action (18 bytes) to leveldb
took 14539ns
> I0627 13:11:56.665426  6600 leveldb.cpp:401] Deleting ~2 keys from leveldb took 7283ns
> I0627 13:11:56.665434  6600 replica.cpp:676] Persisted action at 4
> I0627 13:11:56.665442  6600 replica.cpp:661] Replica learned TRUNCATE action at position
4
> I0627 13:11:56.667680  6594 master.cpp:2769] Ignoring register slave message from slave(34)@192.168.122.164:44870
(fedora-20) as admission is already in progress
> I0627 13:11:56.668217  6594 master.cpp:2821] Registered slave 20140627-131156-2759502016-44870-6574-0
at slave(34)@192.168.122.164:44870 (fedora-20)
> I0627 13:11:56.668607  6594 master.cpp:3967] Adding slave 20140627-131156-2759502016-44870-6574-0
at slave(34)@192.168.122.164:44870 (fedora-20) with cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
> I0627 13:11:56.669155  6597 slave.cpp:768] Registered with master master@192.168.122.164:44870;
given slave ID 20140627-131156-2759502016-44870-6574-0
> I0627 13:11:56.669838  6598 slave.cpp:2325] Received ping from slave-observer(31)@192.168.122.164:44870
> I0627 13:11:56.670250  6596 hierarchical_allocator_process.hpp:444] Added slave 20140627-131156-2759502016-44870-6574-0
(fedora-20) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0627 13:11:56.670301  6596 hierarchical_allocator_process.hpp:706] Performed allocation
for slave 20140627-131156-2759502016-44870-6574-0 in 10553ns
> I0627 13:11:56.675384  6574 sched.cpp:139] Version: 0.20.0
> I0627 13:11:56.676070  6595 sched.cpp:235] New master detected at master@192.168.122.164:44870
> I0627 13:11:56.676098  6595 sched.cpp:285] Authenticating with master master@192.168.122.164:44870
> I0627 13:11:56.676182  6595 authenticatee.hpp:128] Creating new client SASL connection
> I0627 13:11:56.676750  6595 master.cpp:3499] Authenticating scheduler-e3900bac-d18b-4d5d-b15f-a3f012cc18e9@192.168.122.164:44870
> I0627 13:11:56.676846  6595 authenticator.hpp:156] Creating new server SASL connection
> I0627 13:11:56.677340  6595 authenticatee.hpp:219] Received SASL authentication mechanisms:
CRAM-MD5
> I0627 13:11:56.677366  6595 authenticatee.hpp:245] Attempting to authenticate with mechanism
'CRAM-MD5'
> I0627 13:11:56.677393  6595 authenticator.hpp:262] Received SASL authentication start
> I0627 13:11:56.677428  6595 authenticator.hpp:384] Authentication requires more steps
> I0627 13:11:56.677456  6595 authenticatee.hpp:265] Received SASL authentication step
> I0627 13:11:56.677494  6595 authenticator.hpp:290] Received SASL authentication step
> I0627 13:11:56.677511  6595 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: false 
> I0627 13:11:56.677520  6595 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0627 13:11:56.677531  6595 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0627 13:11:56.677844  6595 auxprop.cpp:81] Request to lookup properties for user: 'test-principal'
realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE:
false SASL_AUXPROP_AUTHZID: true 
> I0627 13:11:56.677861  6595 auxprop.cpp:103] Skipping auxiliary property '*userPassword'
since SASL_AUXPROP_AUTHZID == true
> I0627 13:11:56.677867  6595 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5'
since SASL_AUXPROP_AUTHZID == true
> I0627 13:11:56.677881  6595 authenticator.hpp:376] Authentication success
> I0627 13:11:56.678241  6597 authenticatee.hpp:305] Authentication success
> I0627 13:11:56.681001  6596 master.cpp:3539] Successfully authenticated principal 'test-principal'
at scheduler-e3900bac-d18b-4d5d-b15f-a3f012cc18e9@192.168.122.164:44870
> I0627 13:11:56.681349  6597 sched.cpp:359] Successfully authenticated with master master@192.168.122.164:44870
> I0627 13:11:56.681777  6597 sched.cpp:478] Sending registration request to master@192.168.122.164:44870
> I0627 13:11:56.682325  6594 master.cpp:1241] Received registration request from scheduler-e3900bac-d18b-4d5d-b15f-a3f012cc18e9@192.168.122.164:44870
> I0627 13:11:56.682358  6594 master.cpp:1201] Authorizing framework principal 'test-principal'
to receive offers for role '*'
> I0627 13:11:56.682659  6594 master.cpp:1300] Registering framework 20140627-131156-2759502016-44870-6574-0000
at scheduler-e3900bac-d18b-4d5d-b15f-a3f012cc18e9@192.168.122.164:44870
> I0627 13:11:56.682777  6594 hierarchical_allocator_process.hpp:331] Added framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.682829  6594 hierarchical_allocator_process.hpp:750] Offering cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140627-131156-2759502016-44870-6574-0
to framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.682927  6594 hierarchical_allocator_process.hpp:686] Performed allocation
for 1 slaves in 132180ns
> I0627 13:11:56.683008  6594 master.hpp:794] Adding offer 20140627-131156-2759502016-44870-6574-0
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140627-131156-2759502016-44870-6574-0
(fedora-20)
> I0627 13:11:56.683053  6594 master.cpp:3446] Sending 1 offers to framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.683500  6597 sched.cpp:409] Framework registered with 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.684025  6597 sched.cpp:423] Scheduler::registered took 16703ns
> I0627 13:11:56.689298  6597 sched.cpp:546] Scheduler::resourceOffers took 4.635831ms
> I0627 13:11:56.692775  6594 master.hpp:804] Removing offer 20140627-131156-2759502016-44870-6574-0
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140627-131156-2759502016-44870-6574-0
(fedora-20)
> I0627 13:11:56.692838  6594 master.cpp:2125] Processing reply for offers: [ 20140627-131156-2759502016-44870-6574-0
] on slave 20140627-131156-2759502016-44870-6574-0 at slave(34)@192.168.122.164:44870 (fedora-20)
for framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.692873  6594 master.cpp:2211] Authorizing framework principal 'test-principal'
to launch task 1 as user 'jenkins'
> I0627 13:11:56.693167  6594 master.hpp:766] Adding task 1 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave 20140627-131156-2759502016-44870-6574-0 (fedora-20)
> I0627 13:11:56.693205  6594 master.cpp:2277] Launching task 1 of framework 20140627-131156-2759502016-44870-6574-0000
with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140627-131156-2759502016-44870-6574-0
at slave(34)@192.168.122.164:44870 (fedora-20)
> I0627 13:11:56.693332  6594 slave.cpp:1003] Got assigned task 1 for framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.693517  6594 slave.cpp:1113] Launching task 1 for framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.696077  6594 exec.cpp:131] Version: 0.20.0
> I0627 13:11:56.696537  6598 exec.cpp:181] Executor started at: executor(11)@192.168.122.164:44870
with pid 6574
> I0627 13:11:56.696672  6594 slave.cpp:1223] Queuing task '1' for executor default of
framework '20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.697525  6594 slave.cpp:562] Successfully attached file '/tmp/MasterTest_KillTask_1QXLT0/slaves/20140627-131156-2759502016-44870-6574-0/frameworks/20140627-131156-2759502016-44870-6574-0000/executors/default/runs/a2cc8fa6-343b-479d-912b-3e2b9dd9162c'
> I0627 13:11:56.697971  6594 slave.cpp:2470] Monitoring executor 'default' of framework
'20140627-131156-2759502016-44870-6574-0000' in container 'a2cc8fa6-343b-479d-912b-3e2b9dd9162c'
> I0627 13:11:56.698606  6594 slave.cpp:1734] Got registration for executor 'default' of
framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.699300  6600 exec.cpp:205] Executor registered on slave 20140627-131156-2759502016-44870-6574-0
> I0627 13:11:56.700073  6600 exec.cpp:217] Executor::registered took 17412ns
> I0627 13:11:56.700345  6594 slave.cpp:1853] Flushing queued task 1 for executor 'default'
of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.700902  6596 exec.cpp:292] Executor asked to run task '1'
> I0627 13:11:56.700945  6596 exec.cpp:301] Executor::launchTask took 23336ns
> I0627 13:11:56.701958  6596 exec.cpp:524] Executor sending status update TASK_RUNNING
(UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.702426  6594 slave.cpp:2088] Handling status update TASK_RUNNING (UUID:
0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
from executor(11)@192.168.122.164:44870
> I0627 13:11:56.703136  6597 status_update_manager.cpp:320] Received status update TASK_RUNNING
(UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.703160  6597 status_update_manager.cpp:499] Creating StatusUpdate stream
for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.703234  6597 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING
(UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
to master@192.168.122.164:44870
> I0627 13:11:56.703368  6597 master.cpp:3107] Status update TASK_RUNNING (UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d)
for task 1 of framework 20140627-131156-2759502016-44870-6574-0000 from slave 20140627-131156-2759502016-44870-6574-0
at slave(34)@192.168.122.164:44870 (fedora-20)
> I0627 13:11:56.703440  6597 sched.cpp:637] Scheduler::statusUpdate took 16903ns
> I0627 13:11:56.703505  6597 master.cpp:2631] Forwarding status update acknowledgement
0a9e6010-c6b1-45e3-a5a1-782d8c67d50d for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
to slave 20140627-131156-2759502016-44870-6574-0 at slave(34)@192.168.122.164:44870 (fedora-20)
> I0627 13:11:56.704143  6593 master.cpp:2461] Asked to kill task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.704180  6593 master.cpp:2562] Telling slave 20140627-131156-2759502016-44870-6574-0
at slave(34)@192.168.122.164:44870 (fedora-20) to kill task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.704669  6596 status_update_manager.cpp:398] Received status update acknowledgement
(UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.705014  6594 slave.cpp:1279] Asked to kill task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.705463  6597 exec.cpp:312] Executor asked to kill task '1'
> I0627 13:11:56.705505  6597 exec.cpp:321] Executor::killTask took 25106ns
> I0627 13:11:56.706599  6597 exec.cpp:524] Executor sending status update TASK_KILLED
(UUID: e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.707033  6594 slave.cpp:2246] Status update manager successfully handled
status update TASK_RUNNING (UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework
20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.707775  6594 slave.cpp:2252] Sending acknowledgement for status update
TASK_RUNNING (UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
to executor(11)@192.168.122.164:44870
> I0627 13:11:56.708256  6593 exec.cpp:338] Executor received status update acknowledgement
0a9e6010-c6b1-45e3-a5a1-782d8c67d50d for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.708515  6594 slave.cpp:1674] Status update manager successfully handled
status update acknowledgement (UUID: 0a9e6010-c6b1-45e3-a5a1-782d8c67d50d) for task 1 of framework
20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.708971  6594 slave.cpp:2088] Handling status update TASK_KILLED (UUID:
e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
from executor(11)@192.168.122.164:44870
> I0627 13:11:56.709383  6594 slave.cpp:3770] Terminating task 1
> I0627 13:11:56.710197  6595 status_update_manager.cpp:320] Received status update TASK_KILLED
(UUID: e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.710232  6595 status_update_manager.cpp:373] Forwarding status update TASK_KILLED
(UUID: e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
to master@192.168.122.164:44870
> I0627 13:11:56.710336  6595 master.cpp:3107] Status update TASK_KILLED (UUID: e46ef760-d54a-4498-b75d-f2320527ae10)
for task 1 of framework 20140627-131156-2759502016-44870-6574-0000 from slave 20140627-131156-2759502016-44870-6574-0
at slave(34)@192.168.122.164:44870 (fedora-20)
> I0627 13:11:56.710400  6595 master.hpp:784] Removing task 1 with resources cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140627-131156-2759502016-44870-6574-0
(fedora-20)
> I0627 13:11:56.710525  6595 sched.cpp:637] Scheduler::statusUpdate took 14611ns
> I0627 13:11:56.710644  6595 hierarchical_allocator_process.hpp:635] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000]) on slave 20140627-131156-2759502016-44870-6574-0 from
framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.710711  6595 master.cpp:2631] Forwarding status update acknowledgement
e46ef760-d54a-4498-b75d-f2320527ae10 for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
to slave 20140627-131156-2759502016-44870-6574-0 at slave(34)@192.168.122.164:44870 (fedora-20)
> I0627 13:11:56.710813  6574 master.cpp:619] Master terminating
> I0627 13:11:56.711582  6600 sched.cpp:747] Stopping framework '20140627-131156-2759502016-44870-6574-0000'
> I0627 13:11:56.712723  6593 status_update_manager.cpp:398] Received status update acknowledgement
(UUID: e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.712755  6593 status_update_manager.cpp:530] Cleaning up status update
stream for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.713125  6594 slave.cpp:2332] master@192.168.122.164:44870 exited
> W0627 13:11:56.713845  6594 slave.cpp:2335] Master disconnected! Waiting for a new master
to be elected
> I0627 13:11:56.714365  6594 slave.cpp:2246] Status update manager successfully handled
status update TASK_KILLED (UUID: e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework
20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.715390  6594 slave.cpp:2252] Sending acknowledgement for status update
TASK_KILLED (UUID: e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
to executor(11)@192.168.122.164:44870
> I0627 13:11:56.716157  6595 exec.cpp:338] Executor received status update acknowledgement
e46ef760-d54a-4498-b75d-f2320527ae10 for task 1 of framework 20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.716536  6594 slave.cpp:1674] Status update manager successfully handled
status update acknowledgement (UUID: e46ef760-d54a-4498-b75d-f2320527ae10) for task 1 of framework
20140627-131156-2759502016-44870-6574-0000
> I0627 13:11:56.716965  6594 slave.cpp:3812] Completing task 1
> I0627 13:12:56.648658  6600 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:13:56.650368  6600 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:14:56.652971  6600 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:15:56.657176  6596 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:16:56.657906  6596 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:17:56.659015  6596 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:18:56.660163  6594 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:19:56.660965  6594 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> I0627 13:20:56.661873  6600 slave.cpp:2983] Current usage 1.41%. Max allowed age: 6.200973731061285days
> {code}



--
This message was sent by Atlassian JIRA
(v6.2#6252)

Mime
View raw message