[
https://issues.apache.org/jira/browse/MESOS-1594?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14127770#comment-14127770
]
Yan Xu commented on MESOS-1594:
-------------------------------
Another instance on centos-7-gcc Jenkins VM.
{noformat:title=}
[ RUN ] SlaveRecoveryTest/0.ReconcileKillTask
Using temporary directory '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_IJPbbd'
I0909 09:51:40.897189 544 leveldb.cpp:176] Opened db in 1.795293765secs
I0909 09:51:40.903898 544 leveldb.cpp:183] Compacted db in 6.65008ms
I0909 09:51:40.903934 544 leveldb.cpp:198] Created db iterator in 13655ns
I0909 09:51:40.903949 544 leveldb.cpp:204] Seeked to beginning of db in 937ns
I0909 09:51:40.903955 544 leveldb.cpp:273] Iterated through 0 keys in the db
in 511ns
I0909 09:51:40.903985 544 replica.cpp:741] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0909 09:51:40.905460 570 recover.cpp:425] Starting replica recovery
I0909 09:51:40.905555 570 recover.cpp:451] Replica is in EMPTY status
I0909 09:51:40.905923 570 replica.cpp:638] Replica in EMPTY status received a
broadcasted recover request
I0909 09:51:40.905977 570 recover.cpp:188] Received a recover response from a
replica in EMPTY status
I0909 09:51:40.906060 570 recover.cpp:542] Updating replica status to STARTING
I0909 09:51:40.906870 563 master.cpp:286] Master
20140909-095140-1148889280-43580-544 (centos-7) started on 192.168.122.68:43580
I0909 09:51:40.906908 563 master.cpp:332] Master only allowing authenticated
frameworks to register
I0909 09:51:40.906915 563 master.cpp:337] Master only allowing authenticated
slaves to register
I0909 09:51:40.906926 563 credentials.hpp:36] Loading credentials for
authentication from
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_IJPbbd/credentials'
I0909 09:51:40.907069 563 master.cpp:366] Authorization enabled
I0909 09:51:40.907492 563 hierarchical_allocator_process.hpp:299]
Initializing hierarchical allocator process with master :
[email protected]:43580
I0909 09:51:40.907528 563 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0909 09:51:40.907690 563 master.cpp:1212] The newly elected leader is
[email protected]:43580 with id 20140909-095140-1148889280-43580-544
I0909 09:51:40.907703 563 master.cpp:1225] Elected as the leading master!
I0909 09:51:40.907708 563 master.cpp:1043] Recovering from registrar
I0909 09:51:40.907793 563 registrar.cpp:313] Recovering registrar
I0909 09:51:40.913550 570 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 7.435041ms
I0909 09:51:40.913574 570 replica.cpp:320] Persisted replica status to
STARTING
I0909 09:51:40.913655 570 recover.cpp:451] Replica is in STARTING status
I0909 09:51:40.913939 570 replica.cpp:638] Replica in STARTING status
received a broadcasted recover request
I0909 09:51:40.913988 570 recover.cpp:188] Received a recover response from a
replica in STARTING status
I0909 09:51:40.914070 570 recover.cpp:542] Updating replica status to VOTING
I0909 09:51:40.919895 570 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 5.778157ms
I0909 09:51:40.919927 570 replica.cpp:320] Persisted replica status to VOTING
I0909 09:51:40.919983 570 recover.cpp:556] Successfully joined the Paxos group
I0909 09:51:40.920027 570 recover.cpp:440] Recover process terminated
I0909 09:51:40.920142 570 log.cpp:656] Attempting to start the writer
I0909 09:51:40.920397 570 replica.cpp:474] Replica received implicit promise
request with proposal 1
I0909 09:51:40.925762 570 leveldb.cpp:306] Persisting metadata (8 bytes) to
leveldb took 5.343628ms
I0909 09:51:40.925794 570 replica.cpp:342] Persisted promised to 1
I0909 09:51:40.925971 570 coordinator.cpp:230] Coordinator attemping to fill
missing position
I0909 09:51:40.926249 570 replica.cpp:375] Replica received explicit promise
request for position 0 with proposal 2
I0909 09:51:40.931947 570 leveldb.cpp:343] Persisting action (8 bytes) to
leveldb took 5.676183ms
I0909 09:51:40.931980 570 replica.cpp:676] Persisted action at 0
I0909 09:51:40.932229 570 replica.cpp:508] Replica received write request for
position 0
I0909 09:51:40.932255 570 leveldb.cpp:438] Reading position from leveldb took
11652ns
I0909 09:51:40.938361 570 leveldb.cpp:343] Persisting action (14 bytes) to
leveldb took 6.087894ms
I0909 09:51:40.938395 570 replica.cpp:676] Persisted action at 0
I0909 09:51:40.938524 570 replica.cpp:655] Replica received learned notice
for position 0
I0909 09:51:40.943999 570 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 5.451739ms
I0909 09:51:40.944031 570 replica.cpp:676] Persisted action at 0
I0909 09:51:40.944046 570 replica.cpp:661] Replica learned NOP action at
position 0
I0909 09:51:40.944229 570 log.cpp:672] Writer started with ending position 0
I0909 09:51:40.944416 570 leveldb.cpp:438] Reading position from leveldb took
10354ns
I0909 09:51:40.945526 570 registrar.cpp:346] Successfully fetched the
registry (0B)
I0909 09:51:40.945554 570 registrar.cpp:422] Attempting to update the
'registry'
I0909 09:51:40.946728 570 log.cpp:680] Attempting to append 127 bytes to the
log
I0909 09:51:40.946769 570 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 1
I0909 09:51:40.946936 570 replica.cpp:508] Replica received write request for
position 1
I0909 09:51:40.952258 570 leveldb.cpp:343] Persisting action (145 bytes) to
leveldb took 5.300201ms
I0909 09:51:40.952286 570 replica.cpp:676] Persisted action at 1
I0909 09:51:40.952437 570 replica.cpp:655] Replica received learned notice
for position 1
I0909 09:51:40.958236 570 leveldb.cpp:343] Persisting action (147 bytes) to
leveldb took 5.781888ms
I0909 09:51:40.958261 570 replica.cpp:676] Persisted action at 1
I0909 09:51:40.958268 570 replica.cpp:661] Replica learned APPEND action at
position 1
I0909 09:51:40.958499 570 registrar.cpp:479] Successfully updated 'registry'
I0909 09:51:40.958533 570 registrar.cpp:372] Successfully recovered registrar
I0909 09:51:40.958561 570 log.cpp:699] Attempting to truncate the log to 1
I0909 09:51:40.958611 570 master.cpp:1070] Recovered 0 slaves from the
Registry (91B) ; allowing 10mins for slaves to re-register
I0909 09:51:40.958643 570 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 2
I0909 09:51:40.958839 570 replica.cpp:508] Replica received write request for
position 2
I0909 09:51:40.964298 570 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 5.439108ms
I0909 09:51:40.964323 570 replica.cpp:676] Persisted action at 2
I0909 09:51:40.964465 570 replica.cpp:655] Replica received learned notice
for position 2
I0909 09:51:40.969729 570 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 5.226703ms
I0909 09:51:40.969776 570 leveldb.cpp:401] Deleting ~1 keys from leveldb took
21142ns
I0909 09:51:40.969789 570 replica.cpp:676] Persisted action at 2
I0909 09:51:40.969795 570 replica.cpp:661] Replica learned TRUNCATE action at
position 2
I0909 09:51:40.980108 544 containerizer.cpp:89] Using isolation:
posix/cpu,posix/mem
I0909 09:51:40.982628 570 slave.cpp:167] Slave started on
8)@192.168.122.68:43580
I0909 09:51:40.982650 570 credentials.hpp:84] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/credential'
I0909 09:51:40.982750 570 slave.cpp:274] Slave using credential for:
test-principal
I0909 09:51:40.982841 570 slave.cpp:287] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0909 09:51:40.983360 570 slave.cpp:315] Slave hostname: centos-7
I0909 09:51:40.983378 570 slave.cpp:316] Slave checkpoint: true
I0909 09:51:40.983768 570 state.cpp:33] Recovering state from
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta'
I0909 09:51:40.983871 570 status_update_manager.cpp:193] Recovering status
update manager
I0909 09:51:40.983922 570 containerizer.cpp:252] Recovering containerizer
I0909 09:51:40.984138 570 slave.cpp:3202] Finished recovery
I0909 09:51:40.984550 570 slave.cpp:598] New master detected at
[email protected]:43580
I0909 09:51:40.984580 570 slave.cpp:672] Authenticating with master
[email protected]:43580
I0909 09:51:40.984614 570 slave.cpp:645] Detecting new master
I0909 09:51:40.984643 570 status_update_manager.cpp:167] New master detected
at [email protected]:43580
I0909 09:51:40.984671 570 authenticatee.hpp:128] Creating new client SASL
connection
I0909 09:51:40.985360 570 master.cpp:3653] Authenticating
slave(8)@192.168.122.68:43580
I0909 09:51:40.985465 570 authenticator.hpp:156] Creating new server SASL
connection
I0909 09:51:40.986243 570 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0909 09:51:40.986265 570 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0909 09:51:40.986290 570 authenticator.hpp:262] Received SASL authentication
start
I0909 09:51:40.986322 570 authenticator.hpp:384] Authentication requires more
steps
I0909 09:51:40.986346 570 authenticatee.hpp:265] Received SASL authentication
step
I0909 09:51:40.986388 570 authenticator.hpp:290] Received SASL authentication
step
I0909 09:51:40.986410 570 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'centos-7' server FQDN: 'centos-7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0909 09:51:40.986418 570 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0909 09:51:40.986428 570 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0909 09:51:40.986435 570 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'centos-7' server FQDN: 'centos-7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0909 09:51:40.986441 570 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 09:51:40.986446 570 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 09:51:40.986456 570 authenticator.hpp:376] Authentication success
I0909 09:51:40.986490 570 authenticatee.hpp:305] Authentication success
I0909 09:51:40.986510 570 master.cpp:3693] Successfully authenticated
principal 'test-principal' at slave(8)@192.168.122.68:43580
I0909 09:51:40.986567 570 slave.cpp:729] Successfully authenticated with
master [email protected]:43580
I0909 09:51:40.986611 570 slave.cpp:980] Will retry registration in
10.02298ms if necessary
I0909 09:51:40.986747 570 master.cpp:2843] Registering slave at
slave(8)@192.168.122.68:43580 (centos-7) with id
20140909-095140-1148889280-43580-544-0
I0909 09:51:40.986847 570 registrar.cpp:422] Attempting to update the
'registry'
I0909 09:51:40.987818 570 log.cpp:680] Attempting to append 304 bytes to the
log
I0909 09:51:40.987864 570 coordinator.cpp:340] Coordinator attempting to
write APPEND action at position 3
I0909 09:51:40.988065 570 replica.cpp:508] Replica received write request for
position 3
I0909 09:51:40.991019 544 sched.cpp:137] Version: 0.21.0
I0909 09:51:40.991173 563 sched.cpp:233] New master detected at
[email protected]:43580
I0909 09:51:40.991199 563 sched.cpp:283] Authenticating with master
[email protected]:43580
I0909 09:51:40.991260 563 authenticatee.hpp:128] Creating new client SASL
connection
I0909 09:51:40.992020 563 master.cpp:3653] Authenticating
[email protected]:43580
I0909 09:51:40.992122 563 authenticator.hpp:156] Creating new server SASL
connection
I0909 09:51:40.992588 563 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0909 09:51:40.992619 563 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0909 09:51:40.992647 563 authenticator.hpp:262] Received SASL authentication
start
I0909 09:51:40.992677 563 authenticator.hpp:384] Authentication requires more
steps
I0909 09:51:40.992748 563 authenticatee.hpp:265] Received SASL authentication
step
I0909 09:51:40.992854 563 authenticator.hpp:290] Received SASL authentication
step
I0909 09:51:40.992873 563 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'centos-7' server FQDN: 'centos-7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0909 09:51:40.992880 563 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0909 09:51:40.992887 563 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0909 09:51:40.992895 563 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'centos-7' server FQDN: 'centos-7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0909 09:51:40.992902 563 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 09:51:40.992905 563 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 09:51:40.992915 563 authenticator.hpp:376] Authentication success
I0909 09:51:40.992938 563 authenticatee.hpp:305] Authentication success
I0909 09:51:40.992957 563 master.cpp:3693] Successfully authenticated
principal 'test-principal' at
[email protected]:43580
I0909 09:51:40.993015 563 sched.cpp:357] Successfully authenticated with
master [email protected]:43580
I0909 09:51:40.993026 563 sched.cpp:476] Sending registration request to
[email protected]:43580
I0909 09:51:40.993063 563 master.cpp:1331] Received registration request from
[email protected]:43580
I0909 09:51:40.993093 563 master.cpp:1291] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0909 09:51:40.993198 563 master.cpp:1390] Registering framework
20140909-095140-1148889280-43580-544-0000 at
[email protected]:43580
I0909 09:51:40.993289 563 sched.cpp:407] Framework registered with
20140909-095140-1148889280-43580-544-0000
I0909 09:51:40.993310 563 sched.cpp:421] Scheduler::registered took 8514ns
I0909 09:51:40.993348 563 hierarchical_allocator_process.hpp:329] Added
framework 20140909-095140-1148889280-43580-544-0000
I0909 09:51:40.993358 563 hierarchical_allocator_process.hpp:697] No
resources available to allocate!
I0909 09:51:40.993365 563 hierarchical_allocator_process.hpp:659] Performed
allocation for 0 slaves in 6610ns
I0909 09:51:40.995043 570 leveldb.cpp:343] Persisting action (323 bytes) to
leveldb took 6.956739ms
I0909 09:51:40.995069 570 replica.cpp:676] Persisted action at 3
I0909 09:51:40.995234 570 replica.cpp:655] Replica received learned notice
for position 3
I0909 09:51:40.997666 563 slave.cpp:980] Will retry registration in
38.204816ms if necessary
I0909 09:51:40.997764 563 master.cpp:2831] Ignoring register slave message
from slave(8)@192.168.122.68:43580 (centos-7) as admission is already in
progress
I0909 09:51:41.000252 570 leveldb.cpp:343] Persisting action (325 bytes) to
leveldb took 4.9979ms
I0909 09:51:41.000277 570 replica.cpp:676] Persisted action at 3
I0909 09:51:41.000285 570 replica.cpp:661] Replica learned APPEND action at
position 3
I0909 09:51:41.000547 570 registrar.cpp:479] Successfully updated 'registry'
I0909 09:51:41.000612 570 log.cpp:699] Attempting to truncate the log to 3
I0909 09:51:41.000668 570 master.cpp:2883] Registered slave
20140909-095140-1148889280-43580-544-0 at slave(8)@192.168.122.68:43580
(centos-7)
I0909 09:51:41.000682 570 master.cpp:4126] Adding slave
20140909-095140-1148889280-43580-544-0 at slave(8)@192.168.122.68:43580
(centos-7) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0909 09:51:41.000797 570 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 4
I0909 09:51:41.000859 570 slave.cpp:763] Registered with master
[email protected]:43580; given slave ID
20140909-095140-1148889280-43580-544-0
I0909 09:51:41.001266 570 slave.cpp:776] Checkpointing SlaveInfo to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/slave.info'
I0909 09:51:41.001503 570 hierarchical_allocator_process.hpp:442] Added slave
20140909-095140-1148889280-43580-544-0 (centos-7) with cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000] available)
I0909 09:51:41.001555 570 hierarchical_allocator_process.hpp:734] Offering
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 to framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.001622 570 hierarchical_allocator_process.hpp:679] Performed
allocation for slave 20140909-095140-1148889280-43580-544-0 in 85987ns
I0909 09:51:41.001665 570 slave.cpp:2329] Received ping from
slave-observer(7)@192.168.122.68:43580
I0909 09:51:41.001760 570 master.hpp:861] Adding offer
20140909-095140-1148889280-43580-544-0 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 (centos-7)
I0909 09:51:41.001811 570 master.cpp:3600] Sending 1 offers to framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.001915 570 sched.cpp:544] Scheduler::resourceOffers took
16228ns
I0909 09:51:41.002053 570 replica.cpp:508] Replica received write request for
position 4
I0909 09:51:41.003602 563 master.hpp:871] Removing offer
20140909-095140-1148889280-43580-544-0 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 (centos-7)
I0909 09:51:41.003660 563 master.cpp:2201] Processing reply for offers: [
20140909-095140-1148889280-43580-544-0 ] on slave
20140909-095140-1148889280-43580-544-0 at slave(8)@192.168.122.68:43580
(centos-7) for framework 20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.003690 563 master.cpp:2284] Authorizing framework principal
'test-principal' to launch task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 as user
'jenkins'
I0909 09:51:41.003962 563 master.hpp:833] Adding task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 (centos-7)
I0909 09:51:41.003998 563 master.cpp:2350] Launching task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 with resources cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 at slave(8)@192.168.122.68:43580
(centos-7)
I0909 09:51:41.004109 563 slave.cpp:1011] Got assigned task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 for framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.004178 563 slave.cpp:3548] Checkpointing FrameworkInfo to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/framework.info'
I0909 09:51:41.004513 563 slave.cpp:3555] Checkpointing framework pid
'[email protected]:43580' to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/framework.pid'
I0909 09:51:41.004886 563 slave.cpp:1121] Launching task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 for framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.006407 563 slave.cpp:3866] Checkpointing ExecutorInfo to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/executor.info'
I0909 09:51:41.007109 563 slave.cpp:3977] Checkpointing TaskInfo to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/runs/bfb0723d-ad52-4dc8-b95e-4610ddb9a819/tasks/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/task.info'
I0909 09:51:41.007434 565 containerizer.cpp:394] Starting container
'bfb0723d-ad52-4dc8-b95e-4610ddb9a819' for executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
'20140909-095140-1148889280-43580-544-0000'
I0909 09:51:41.008872 565 launcher.cpp:137] Forked child with pid '901' for
container 'bfb0723d-ad52-4dc8-b95e-4610ddb9a819'
I0909 09:51:41.009019 565 containerizer.cpp:678] Checkpointing executor's
forked pid 901 to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/runs/bfb0723d-ad52-4dc8-b95e-4610ddb9a819/pids/forked.pid'
I0909 09:51:41.010238 563 slave.cpp:1231] Queuing task
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' for executor
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
'20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.010334 563 slave.cpp:552] Successfully attached file
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/runs/bfb0723d-ad52-4dc8-b95e-4610ddb9a819'
I0909 09:51:41.011068 565 containerizer.cpp:510] Fetching URIs for container
'bfb0723d-ad52-4dc8-b95e-4610ddb9a819' using command
'/var/jenkins/workspace/mesos-centos-7-gcc/src/mesos-fetcher'
I0909 09:51:41.017060 570 leveldb.cpp:343] Persisting action (16 bytes) to
leveldb took 14.916871ms
I0909 09:51:41.017137 570 replica.cpp:676] Persisted action at 4
I0909 09:51:41.017464 570 replica.cpp:655] Replica received learned notice
for position 4
I0909 09:51:41.032018 570 leveldb.cpp:343] Persisting action (18 bytes) to
leveldb took 14.522155ms
I0909 09:51:41.032094 570 leveldb.cpp:401] Deleting ~2 keys from leveldb took
32909ns
I0909 09:51:41.032109 570 replica.cpp:676] Persisted action at 4
I0909 09:51:41.032119 570 replica.cpp:661] Replica learned TRUNCATE action at
position 4
I0909 09:51:41.877382 570 slave.cpp:2542] Monitoring executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
'20140909-095140-1148889280-43580-544-0000' in container
'bfb0723d-ad52-4dc8-b95e-4610ddb9a819'
I0909 09:51:41.915293 570 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 32237ns
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0909 09:51:41.916180 901 process.cpp:1771] libprocess is initialized on
192.168.122.68:50645 for 8 cpus
I0909 09:51:41.916468 901 logging.cpp:177] Logging to STDERR
I0909 09:51:41.917357 901 exec.cpp:132] Version: 0.21.0
I0909 09:51:41.919569 952 exec.cpp:182] Executor started at:
executor(1)@192.168.122.68:50645 with pid 901
I0909 09:51:41.920593 570 slave.cpp:1741] Got registration for executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.920641 570 slave.cpp:1826] Checkpointing executor pid
'executor(1)@192.168.122.68:50645' to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/runs/bfb0723d-ad52-4dc8-b95e-4610ddb9a819/pids/libprocess.pid'
I0909 09:51:41.922448 570 slave.cpp:1859] Flushing queued task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 for executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.923576 952 exec.cpp:206] Executor registered on slave
20140909-095140-1148889280-43580-544-0
I0909 09:51:41.924360 952 exec.cpp:218] Executor::registered took 80708ns
I0909 09:51:41.924443 952 exec.cpp:293] Executor asked to run task
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17'
I0909 09:51:41.924475 952 exec.cpp:302] Executor::launchTask took 21066ns
Registered executor on centos-7
Starting task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17
sh -c 'sleep 1000'
Forked command at 956
I0909 09:51:41.929075 952 exec.cpp:525] Executor sending status update
TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.929788 570 slave.cpp:2093] Handling status update TASK_RUNNING
(UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 from executor(1)@192.168.122.68:50645
I0909 09:51:41.929898 570 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.929911 570 status_update_manager.cpp:499] Creating
StatusUpdate stream for task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.930209 570 status_update_manager.hpp:342] Checkpointing UPDATE
for status update TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for
task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.941706 570 status_update_manager.cpp:373] Forwarding status
update TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 to [email protected]:43580
I0909 09:51:41.941956 570 master.cpp:3212] Forwarding status update
TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.941999 570 master.cpp:3178] Status update TASK_RUNNING (UUID:
22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 from slave
20140909-095140-1148889280-43580-544-0 at slave(8)@192.168.122.68:43580
(centos-7)
I0909 09:51:41.942039 570 slave.cpp:2250] Status update manager successfully
handled status update TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96)
for task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.942049 570 slave.cpp:2256] Sending acknowledgement for status
update TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 to executor(1)@192.168.122.68:50645
I0909 09:51:41.942381 570 sched.cpp:635] Scheduler::statusUpdate took 15922ns
I0909 09:51:41.942433 570 master.cpp:2693] Forwarding status update
acknowledgement 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96 for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 to slave
20140909-095140-1148889280-43580-544-0 at slave(8)@192.168.122.68:43580
(centos-7)
I0909 09:51:41.942498 570 status_update_manager.cpp:398] Received status
update acknowledgement (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.942515 570 status_update_manager.hpp:342] Checkpointing ACK
for status update TASK_RUNNING (UUID: 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for
task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.943263 952 exec.cpp:339] Executor received status update
acknowledgement 22d70b8d-ee74-40e9-b6fb-0224d1c5fa96 for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.954205 570 slave.cpp:1681] Status update manager successfully
handled status update acknowledgement (UUID:
22d70b8d-ee74-40e9-b6fb-0224d1c5fa96) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.954396 544 slave.cpp:475] Slave terminating
I0909 09:51:41.954929 544 containerizer.cpp:89] Using isolation:
posix/cpu,posix/mem
I0909 09:51:41.956308 568 master.cpp:791] Slave
20140909-095140-1148889280-43580-544-0 at slave(8)@192.168.122.68:43580
(centos-7) disconnected
I0909 09:51:41.956329 568 master.cpp:1712] Disconnecting slave
20140909-095140-1148889280-43580-544-0
I0909 09:51:41.956609 568 hierarchical_allocator_process.hpp:481] Slave
20140909-095140-1148889280-43580-544-0 deactivated
I0909 09:51:41.956657 568 master.cpp:2527] Asked to kill task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.957993 568 slave.cpp:167] Slave started on
9)@192.168.122.68:43580
I0909 09:51:41.958017 568 credentials.hpp:84] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/credential'
I0909 09:51:41.958104 568 slave.cpp:274] Slave using credential for:
test-principal
I0909 09:51:41.958187 568 slave.cpp:287] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0909 09:51:41.958969 568 slave.cpp:315] Slave hostname: centos-7
I0909 09:51:41.958994 568 slave.cpp:316] Slave checkpoint: true
I0909 09:51:41.959348 568 state.cpp:33] Recovering state from
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta'
I0909 09:51:41.960574 568 slave.cpp:3273] Recovering framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.960600 568 slave.cpp:3714] Recovering executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.960989 568 status_update_manager.cpp:193] Recovering status
update manager
I0909 09:51:41.961002 568 status_update_manager.cpp:201] Recovering executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.961019 568 status_update_manager.cpp:499] Creating
StatusUpdate stream for task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.961112 568 status_update_manager.hpp:306] Replaying status
update stream for task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17
I0909 09:51:41.961216 568 slave.cpp:552] Successfully attached file
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/runs/bfb0723d-ad52-4dc8-b95e-4610ddb9a819'
I0909 09:51:41.961318 568 containerizer.cpp:252] Recovering containerizer
I0909 09:51:41.961335 568 containerizer.cpp:294] Recovering container
'bfb0723d-ad52-4dc8-b95e-4610ddb9a819' for executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.962028 568 slave.cpp:3143] Sending reconnect request to
executor b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 at executor(1)@192.168.122.68:50645
I0909 09:51:41.962991 952 exec.cpp:252] Received reconnect request from slave
20140909-095140-1148889280-43580-544-0
I0909 09:51:41.963770 570 slave.cpp:1919] Re-registering executor
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:41.964565 952 exec.cpp:229] Executor re-registered on slave
20140909-095140-1148889280-43580-544-0
I0909 09:51:41.965406 952 exec.cpp:241] Executor::reregistered took 29855ns
Re-registered executor on centos-7
I0909 09:51:42.949388 570 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 9516ns
I0909 09:51:43.952998 570 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 72052ns
I0909 09:51:43.974743 571 slave.cpp:2042] Cleaning up un-reregistered
executors
I0909 09:51:43.974859 571 slave.cpp:3202] Finished recovery
I0909 09:51:43.975504 571 slave.cpp:598] New master detected at
[email protected]:43580
I0909 09:51:43.975543 571 slave.cpp:672] Authenticating with master
[email protected]:43580
I0909 09:51:43.975636 571 slave.cpp:645] Detecting new master
I0909 09:51:43.975673 571 status_update_manager.cpp:167] New master detected
at [email protected]:43580
I0909 09:51:43.975770 571 authenticatee.hpp:128] Creating new client SASL
connection
I0909 09:51:43.980680 571 master.cpp:3653] Authenticating
slave(9)@192.168.122.68:43580
I0909 09:51:43.980831 571 authenticator.hpp:156] Creating new server SASL
connection
I0909 09:51:43.992446 571 authenticatee.hpp:219] Received SASL authentication
mechanisms: CRAM-MD5
I0909 09:51:43.992470 571 authenticatee.hpp:245] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0909 09:51:43.992492 571 authenticator.hpp:262] Received SASL authentication
start
I0909 09:51:43.992528 571 authenticator.hpp:384] Authentication requires more
steps
I0909 09:51:43.992552 571 authenticatee.hpp:265] Received SASL authentication
step
I0909 09:51:43.992581 571 authenticator.hpp:290] Received SASL authentication
step
I0909 09:51:43.992605 571 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'centos-7' server FQDN: 'centos-7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0909 09:51:43.992614 571 auxprop.cpp:153] Looking up auxiliary property
'*userPassword'
I0909 09:51:43.992624 571 auxprop.cpp:153] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0909 09:51:43.992638 571 auxprop.cpp:81] Request to lookup properties for
user: 'test-principal' realm: 'centos-7' server FQDN: 'centos-7'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0909 09:51:43.992645 571 auxprop.cpp:103] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 09:51:43.992650 571 auxprop.cpp:103] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 09:51:43.992660 571 authenticator.hpp:376] Authentication success
I0909 09:51:43.992686 571 authenticatee.hpp:305] Authentication success
I0909 09:51:43.992704 571 master.cpp:3693] Successfully authenticated
principal 'test-principal' at slave(9)@192.168.122.68:43580
I0909 09:51:43.992817 571 slave.cpp:729] Successfully authenticated with
master [email protected]:43580
I0909 09:51:43.992920 571 slave.cpp:980] Will retry registration in
2.002547ms if necessary
W0909 09:51:43.993034 571 master.cpp:2958] Slave at
slave(9)@192.168.122.68:43580 (centos-7) is being allowed to re-register with
an already in use id (20140909-095140-1148889280-43580-544-0)
W0909 09:51:43.993115 571 master.cpp:3826] Slave
20140909-095140-1148889280-43580-544-0 at slave(9)@192.168.122.68:43580
(centos-7) has non-terminal task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 that is
supposed to be killed. Killing it now!
I0909 09:51:43.993190 571 slave.cpp:825] Re-registered with master
[email protected]:43580
I0909 09:51:43.993214 571 slave.cpp:1286] Asked to kill task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:43.993443 571 slave.cpp:1591] Updating framework
20140909-095140-1148889280-43580-544-0000 pid to
[email protected]:43580
I0909 09:51:43.993474 571 slave.cpp:1599] Checkpointing framework pid
'[email protected]:43580' to
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/framework.pid'
I0909 09:51:43.993677 567 hierarchical_allocator_process.hpp:495] Slave
20140909-095140-1148889280-43580-544-0 reactivated
I0909 09:51:44.121048 952 exec.cpp:313] Executor asked to kill task
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17'
I0909 09:51:44.121096 952 exec.cpp:322] Executor::killTask took 17461ns
Shutting down
Sending SIGTERM to process tree at pid 956
Killing the following process trees:
[
--- 956 sleep 1000
]
Command terminated with signal Terminated (pid: 956)
I0909 09:51:44.976544 949 exec.cpp:525] Executor sending status update
TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.977221 563 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 45292ns
I0909 09:51:44.977294 563 slave.cpp:2093] Handling status update TASK_KILLED
(UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 from executor(1)@192.168.122.68:50645
I0909 09:51:44.977352 563 slave.cpp:3913] Terminating task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17
I0909 09:51:44.977848 563 status_update_manager.cpp:320] Received status
update TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.977874 563 status_update_manager.hpp:342] Checkpointing UPDATE
for status update TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for
task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.990294 563 status_update_manager.cpp:373] Forwarding status
update TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 to [email protected]:43580
I0909 09:51:44.990542 563 master.cpp:3212] Forwarding status update
TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.990581 563 master.cpp:3178] Status update TASK_KILLED (UUID:
1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 from slave
20140909-095140-1148889280-43580-544-0 at slave(9)@192.168.122.68:43580
(centos-7)
I0909 09:51:44.990669 563 master.hpp:851] Removing task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 (centos-7)
I0909 09:51:44.990814 563 slave.cpp:2250] Status update manager successfully
handled status update TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da)
for task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.990829 563 slave.cpp:2256] Sending acknowledgement for status
update TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 to executor(1)@192.168.122.68:50645
I0909 09:51:44.991266 563 sched.cpp:635] Scheduler::statusUpdate took 71953ns
I0909 09:51:44.991360 563 hierarchical_allocator_process.hpp:563] Recovered
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total
allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on
slave 20140909-095140-1148889280-43580-544-0 from framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.991443 563 master.cpp:2693] Forwarding status update
acknowledgement 1fb55fe4-b0e3-4d80-8429-6d6a280583da for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000 to slave
20140909-095140-1148889280-43580-544-0 at slave(9)@192.168.122.68:43580
(centos-7)
I0909 09:51:44.991580 563 status_update_manager.cpp:398] Received status
update acknowledgement (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.991601 563 status_update_manager.hpp:342] Checkpointing ACK
for status update TASK_KILLED (UUID: 1fb55fe4-b0e3-4d80-8429-6d6a280583da) for
task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:44.992183 949 exec.cpp:339] Executor received status update
acknowledgement 1fb55fe4-b0e3-4d80-8429-6d6a280583da for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:45.027616 563 status_update_manager.cpp:530] Cleaning up status
update stream for task b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:45.027806 563 slave.cpp:1681] Status update manager successfully
handled status update acknowledgement (UUID:
1fb55fe4-b0e3-4d80-8429-6d6a280583da) for task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17 of framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:45.027838 563 slave.cpp:3952] Completing task
b81d5e8b-cd35-4c14-8a47-a5f5a3777f17
I0909 09:51:45.911133 565 master.cpp:120] No whitelist given. Advertising
offers for all slaves
I0909 09:51:45.980281 571 hierarchical_allocator_process.hpp:734] Offering
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 to framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:45.980523 571 hierarchical_allocator_process.hpp:659] Performed
allocation for 1 slaves in 433319ns
I0909 09:51:45.980589 571 containerizer.cpp:997] Executor for container
'bfb0723d-ad52-4dc8-b95e-4610ddb9a819' has exited
I0909 09:51:45.980612 571 containerizer.cpp:882] Destroying container
'bfb0723d-ad52-4dc8-b95e-4610ddb9a819'
I0909 09:51:45.990910 565 master.hpp:861] Adding offer
20140909-095140-1148889280-43580-544-1 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 (centos-7)
I0909 09:51:45.991014 565 master.cpp:3600] Sending 1 offers to framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:45.991368 565 sched.cpp:544] Scheduler::resourceOffers took
35039ns
I0909 09:51:45.991673 544 master.cpp:650] Master terminating
I0909 09:51:45.991749 544 master.hpp:871] Removing offer
20140909-095140-1148889280-43580-544-1 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
20140909-095140-1148889280-43580-544-0 (centos-7)
I0909 09:51:45.993424 567 sched.cpp:745] Stopping framework
'20140909-095140-1148889280-43580-544-0000'
I0909 09:51:45.993504 567 slave.cpp:2361] [email protected]:43580 exited
W0909 09:51:45.993525 567 slave.cpp:2364] Master disconnected! Waiting for a
new master to be elected
W0909 09:51:46.006973 571 containerizer.cpp:872] Ignoring destroy of unknown
container: bfb0723d-ad52-4dc8-b95e-4610ddb9a819
I0909 09:51:46.007072 571 slave.cpp:2600] Executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
20140909-095140-1148889280-43580-544-0000 exited with status 0
I0909 09:51:46.007222 571 slave.cpp:2736] Cleaning up executor
'b81d5e8b-cd35-4c14-8a47-a5f5a3777f17' of framework
20140909-095140-1148889280-43580-544-0000
./tests/cluster.hpp:530: Failure
(wait).failure(): Unknown container: bfb0723d-ad52-4dc8-b95e-4610ddb9a819
I0909 09:51:46.010267 571 slave.cpp:2811] Cleaning up framework
20140909-095140-1148889280-43580-544-0000
I0909 09:51:46.010457 571 gc.cpp:56] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/runs/bfb0723d-ad52-4dc8-b95e-4610ddb9a819'
for gc 6.9999998843763days in the future
I0909 09:51:46.010556 571 gc.cpp:56] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17'
for gc 6.99999988291556days in the future
I0909 09:51:46.010619 571 gc.cpp:56] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17/runs/bfb0723d-ad52-4dc8-b95e-4610ddb9a819'
for gc 6.99999988221037days in the future
I0909 09:51:46.010679 571 gc.cpp:56] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000/executors/b81d5e8b-cd35-4c14-8a47-a5f5a3777f17'
for gc 6.99999988152889days in the future
I0909 09:51:46.010767 571 gc.cpp:56] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000'
for gc 6.99999988012741days in the future
I0909 09:51:46.010838 571 gc.cpp:56] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconcileKillTask_w02LJn/meta/slaves/20140909-095140-1148889280-43580-544-0/frameworks/20140909-095140-1148889280-43580-544-0000'
for gc 6.99999987967704days in the future
I0909 09:51:46.010892 571 status_update_manager.cpp:282] Closing status
update streams for framework 20140909-095140-1148889280-43580-544-0000
*** Aborted at 1410270706 (unix time) try "date -d @1410270706" if you are
using GNU date ***
PC: @ 0x504973 mesos::internal::tests::Cluster::Slaves::shutdown()
*** SIGSEGV (@0x0) received by PID 544 (TID 0x7f61f2183840) from PID 0; stack
trace: ***
@ 0x7f61f0344130 (unknown)
@ 0x504973 mesos::internal::tests::Cluster::Slaves::shutdown()
@ 0x797ff4 mesos::internal::tests::MesosTest::ShutdownSlaves()
@ 0x797a69 mesos::internal::tests::ContainerizerTest<>::TearDown()
@ 0x984253
testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x97b4d0 testing::Test::Run()
@ 0x97b5ae testing::TestInfo::Run()
@ 0x97b6b5 testing::TestCase::Run()
@ 0x97b958 testing::internal::UnitTestImpl::RunAllTests()
@ 0x97bbe7 testing::UnitTest::Run()
@ 0x491beb main
@ 0x7f61eeed6af5 __libc_start_main
@ 0x4a01f9 (unknown)
make[3]: *** [check-local] Segmentation fault (core dumped)
{noformat}
> SlaveRecoveryTest/0.ReconcileKillTask is flaky
> ----------------------------------------------
>
> Key: MESOS-1594
> URL: https://issues.apache.org/jira/browse/MESOS-1594
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.20.0
> Environment: Ubuntu 12.10 with GCC
> Reporter: Vinod Kone
>
> Observed this on Jenkins.
> {code}
> [ RUN ] SlaveRecoveryTest/0.ReconcileKillTask
> Using temporary directory '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_3zJ6DG'
> I0714 15:08:43.915114 27216 leveldb.cpp:176] Opened db in 474.695188ms
> I0714 15:08:43.933645 27216 leveldb.cpp:183] Compacted db in 18.068942ms
> I0714 15:08:43.934129 27216 leveldb.cpp:198] Created db iterator in 7860ns
> I0714 15:08:43.934439 27216 leveldb.cpp:204] Seeked to beginning of db in
> 2560ns
> I0714 15:08:43.934779 27216 leveldb.cpp:273] Iterated through 0 keys in the
> db in 1400ns
> I0714 15:08:43.935098 27216 replica.cpp:741] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0714 15:08:43.936027 27238 recover.cpp:425] Starting replica recovery
> I0714 15:08:43.936225 27238 recover.cpp:451] Replica is in EMPTY status
> I0714 15:08:43.936867 27238 replica.cpp:638] Replica in EMPTY status received
> a broadcasted recover request
> I0714 15:08:43.937049 27238 recover.cpp:188] Received a recover response from
> a replica in EMPTY status
> I0714 15:08:43.937232 27238 recover.cpp:542] Updating replica status to
> STARTING
> I0714 15:08:43.945600 27235 master.cpp:288] Master
> 20140714-150843-16842879-55850-27216 (quantal) started on 127.0.1.1:55850
> I0714 15:08:43.945643 27235 master.cpp:325] Master only allowing
> authenticated frameworks to register
> I0714 15:08:43.945651 27235 master.cpp:330] Master only allowing
> authenticated slaves to register
> I0714 15:08:43.945658 27235 credentials.hpp:36] Loading credentials for
> authentication from
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_3zJ6DG/credentials'
> I0714 15:08:43.945808 27235 master.cpp:359] Authorization enabled
> I0714 15:08:43.946369 27235 hierarchical_allocator_process.hpp:301]
> Initializing hierarchical allocator process with master :
> [email protected]:55850
> I0714 15:08:43.946419 27235 master.cpp:122] No whitelist given. Advertising
> offers for all slaves
> I0714 15:08:43.946614 27235 master.cpp:1128] The newly elected leader is
> [email protected]:55850 with id 20140714-150843-16842879-55850-27216
> I0714 15:08:43.946630 27235 master.cpp:1141] Elected as the leading master!
> I0714 15:08:43.946637 27235 master.cpp:959] Recovering from registrar
> I0714 15:08:43.946707 27235 registrar.cpp:313] Recovering registrar
> I0714 15:08:43.957895 27238 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 20.529301ms
> I0714 15:08:43.957978 27238 replica.cpp:320] Persisted replica status to
> STARTING
> I0714 15:08:43.958142 27238 recover.cpp:451] Replica is in STARTING status
> I0714 15:08:43.958664 27238 replica.cpp:638] Replica in STARTING status
> received a broadcasted recover request
> I0714 15:08:43.958762 27238 recover.cpp:188] Received a recover response from
> a replica in STARTING status
> I0714 15:08:43.958945 27238 recover.cpp:542] Updating replica status to VOTING
> I0714 15:08:43.975685 27238 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 16.646136ms
> I0714 15:08:43.976367 27238 replica.cpp:320] Persisted replica status to
> VOTING
> I0714 15:08:43.976824 27241 recover.cpp:556] Successfully joined the Paxos
> group
> I0714 15:08:43.977072 27242 recover.cpp:440] Recover process terminated
> I0714 15:08:43.980590 27236 log.cpp:656] Attempting to start the writer
> I0714 15:08:43.981385 27236 replica.cpp:474] Replica received implicit
> promise request with proposal 1
> I0714 15:08:43.999141 27236 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 17.705787ms
> I0714 15:08:43.999222 27236 replica.cpp:342] Persisted promised to 1
> I0714 15:08:44.004451 27240 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0714 15:08:44.004914 27240 replica.cpp:375] Replica received explicit
> promise request for position 0 with proposal 2
> I0714 15:08:44.021456 27240 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 16.499775ms
> I0714 15:08:44.021533 27240 replica.cpp:676] Persisted action at 0
> I0714 15:08:44.022006 27240 replica.cpp:508] Replica received write request
> for position 0
> I0714 15:08:44.022043 27240 leveldb.cpp:438] Reading position from leveldb
> took 21376ns
> I0714 15:08:44.035969 27240 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 13.885907ms
> I0714 15:08:44.036365 27240 replica.cpp:676] Persisted action at 0
> I0714 15:08:44.040156 27238 replica.cpp:655] Replica received learned notice
> for position 0
> I0714 15:08:44.058082 27238 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 17.860707ms
> I0714 15:08:44.058161 27238 replica.cpp:676] Persisted action at 0
> I0714 15:08:44.058176 27238 replica.cpp:661] Replica learned NOP action at
> position 0
> I0714 15:08:44.058526 27238 log.cpp:672] Writer started with ending position 0
> I0714 15:08:44.058872 27238 leveldb.cpp:438] Reading position from leveldb
> took 25660ns
> I0714 15:08:44.060556 27238 registrar.cpp:346] Successfully fetched the
> registry (0B)
> I0714 15:08:44.060845 27238 registrar.cpp:422] Attempting to update the
> 'registry'
> I0714 15:08:44.062304 27238 log.cpp:680] Attempting to append 120 bytes to
> the log
> I0714 15:08:44.062866 27236 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0714 15:08:44.063154 27236 replica.cpp:508] Replica received write request
> for position 1
> I0714 15:08:44.082813 27236 leveldb.cpp:343] Persisting action (137 bytes) to
> leveldb took 19.61683ms
> I0714 15:08:44.082890 27236 replica.cpp:676] Persisted action at 1
> I0714 15:08:44.083256 27236 replica.cpp:655] Replica received learned notice
> for position 1
> I0714 15:08:44.097398 27236 leveldb.cpp:343] Persisting action (139 bytes) to
> leveldb took 14.104796ms
> I0714 15:08:44.097475 27236 replica.cpp:676] Persisted action at 1
> I0714 15:08:44.097488 27236 replica.cpp:661] Replica learned APPEND action at
> position 1
> I0714 15:08:44.098569 27236 registrar.cpp:479] Successfully updated 'registry'
> I0714 15:08:44.098906 27240 log.cpp:699] Attempting to truncate the log to 1
> I0714 15:08:44.099608 27240 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0714 15:08:44.100005 27240 replica.cpp:508] Replica received write request
> for position 2
> I0714 15:08:44.100566 27236 registrar.cpp:372] Successfully recovered
> registrar
> I0714 15:08:44.101227 27239 master.cpp:986] Recovered 0 slaves from the
> Registry (84B) ; allowing 10mins for slaves to re-register
> I0714 15:08:44.118376 27240 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 18.329495ms
> I0714 15:08:44.118455 27240 replica.cpp:676] Persisted action at 2
> I0714 15:08:44.122258 27242 replica.cpp:655] Replica received learned notice
> for position 2
> I0714 15:08:44.137336 27242 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 15.023553ms
> I0714 15:08:44.137460 27242 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 55049ns
> I0714 15:08:44.137480 27242 replica.cpp:676] Persisted action at 2
> I0714 15:08:44.137492 27242 replica.cpp:661] Replica learned TRUNCATE action
> at position 2
> I0714 15:08:44.143729 27216 containerizer.cpp:124] Using isolation:
> posix/cpu,posix/mem
> I0714 15:08:44.145934 27242 slave.cpp:168] Slave started on
> 43)@127.0.1.1:55850
> I0714 15:08:44.145953 27242 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/credential'
> I0714 15:08:44.146040 27242 slave.cpp:266] Slave using credential for:
> test-principal
> I0714 15:08:44.146136 27242 slave.cpp:279] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0714 15:08:44.146198 27242 slave.cpp:324] Slave hostname: quantal
> I0714 15:08:44.146209 27242 slave.cpp:325] Slave checkpoint: true
> I0714 15:08:44.146708 27242 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta'
> I0714 15:08:44.146824 27242 status_update_manager.cpp:193] Recovering status
> update manager
> I0714 15:08:44.146901 27242 containerizer.cpp:287] Recovering containerizer
> I0714 15:08:44.147228 27242 slave.cpp:3126] Finished recovery
> I0714 15:08:44.147531 27242 slave.cpp:599] New master detected at
> [email protected]:55850
> I0714 15:08:44.147562 27242 slave.cpp:675] Authenticating with master
> [email protected]:55850
> I0714 15:08:44.147614 27242 slave.cpp:648] Detecting new master
> I0714 15:08:44.147652 27242 status_update_manager.cpp:167] New master
> detected at [email protected]:55850
> I0714 15:08:44.147691 27242 authenticatee.hpp:128] Creating new client SASL
> connection
> I0714 15:08:44.148533 27235 master.cpp:3507] Authenticating
> slave(43)@127.0.1.1:55850
> I0714 15:08:44.148666 27235 authenticator.hpp:156] Creating new server SASL
> connection
> I0714 15:08:44.149054 27242 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0714 15:08:44.149447 27242 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0714 15:08:44.149917 27236 authenticator.hpp:262] Received SASL
> authentication start
> I0714 15:08:44.149974 27236 authenticator.hpp:384] Authentication requires
> more steps
> I0714 15:08:44.150208 27242 authenticatee.hpp:265] Received SASL
> authentication step
> I0714 15:08:44.150720 27239 authenticator.hpp:290] Received SASL
> authentication step
> I0714 15:08:44.150749 27239 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0714 15:08:44.150758 27239 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0714 15:08:44.150771 27239 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0714 15:08:44.150781 27239 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0714 15:08:44.150787 27239 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0714 15:08:44.150792 27239 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0714 15:08:44.150804 27239 authenticator.hpp:376] Authentication success
> I0714 15:08:44.150848 27239 master.cpp:3547] Successfully authenticated
> principal 'test-principal' at slave(43)@127.0.1.1:55850
> I0714 15:08:44.157696 27242 authenticatee.hpp:305] Authentication success
> I0714 15:08:44.158855 27242 slave.cpp:732] Successfully authenticated with
> master [email protected]:55850
> I0714 15:08:44.158936 27242 slave.cpp:970] Will retry registration in
> 10.352612ms if necessary
> I0714 15:08:44.161813 27216 sched.cpp:139] Version: 0.20.0
> I0714 15:08:44.162608 27236 sched.cpp:235] New master detected at
> [email protected]:55850
> I0714 15:08:44.162637 27236 sched.cpp:285] Authenticating with master
> [email protected]:55850
> I0714 15:08:44.162747 27236 authenticatee.hpp:128] Creating new client SASL
> connection
> I0714 15:08:44.163506 27239 master.cpp:2789] Registering slave at
> slave(43)@127.0.1.1:55850 (quantal) with id
> 20140714-150843-16842879-55850-27216-0
> I0714 15:08:44.164086 27238 registrar.cpp:422] Attempting to update the
> 'registry'
> I0714 15:08:44.165694 27238 log.cpp:680] Attempting to append 295 bytes to
> the log
> I0714 15:08:44.166231 27240 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0714 15:08:44.166517 27240 replica.cpp:508] Replica received write request
> for position 3
> I0714 15:08:44.167199 27239 master.cpp:3507] Authenticating
> [email protected]:55850
> I0714 15:08:44.167867 27241 authenticator.hpp:156] Creating new server SASL
> connection
> I0714 15:08:44.168058 27241 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0714 15:08:44.168081 27241 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0714 15:08:44.168107 27241 authenticator.hpp:262] Received SASL
> authentication start
> I0714 15:08:44.168149 27241 authenticator.hpp:384] Authentication requires
> more steps
> I0714 15:08:44.168176 27241 authenticatee.hpp:265] Received SASL
> authentication step
> I0714 15:08:44.168215 27241 authenticator.hpp:290] Received SASL
> authentication step
> I0714 15:08:44.168233 27241 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0714 15:08:44.168793 27241 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0714 15:08:44.168820 27241 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0714 15:08:44.168834 27241 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0714 15:08:44.168840 27241 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0714 15:08:44.168845 27241 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0714 15:08:44.168858 27241 authenticator.hpp:376] Authentication success
> I0714 15:08:44.168895 27241 authenticatee.hpp:305] Authentication success
> I0714 15:08:44.168970 27241 sched.cpp:359] Successfully authenticated with
> master [email protected]:55850
> I0714 15:08:44.168987 27241 sched.cpp:478] Sending registration request to
> [email protected]:55850
> I0714 15:08:44.169426 27239 master.cpp:1239] Queuing up registration request
> from [email protected]:55850 because
> authentication is still in progress
> I0714 15:08:44.169958 27239 master.cpp:3547] Successfully authenticated
> principal 'test-principal' at
> [email protected]:55850
> I0714 15:08:44.170440 27241 slave.cpp:970] Will retry registration in
> 8.76707ms if necessary
> I0714 15:08:44.175359 27239 master.cpp:2777] Ignoring register slave message
> from slave(43)@127.0.1.1:55850 (quantal) as admission is already in progress
> I0714 15:08:44.175916 27239 master.cpp:1247] Received registration request
> from [email protected]:55850
> I0714 15:08:44.176298 27239 master.cpp:1207] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0714 15:08:44.176858 27239 master.cpp:1306] Registering framework
> 20140714-150843-16842879-55850-27216-0000 at
> [email protected]:55850
> I0714 15:08:44.177408 27236 sched.cpp:409] Framework registered with
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.177443 27236 sched.cpp:423] Scheduler::registered took 12527ns
> I0714 15:08:44.177727 27241 hierarchical_allocator_process.hpp:331] Added
> framework 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.177747 27241 hierarchical_allocator_process.hpp:724] No
> resources available to allocate!
> I0714 15:08:44.177753 27241 hierarchical_allocator_process.hpp:686] Performed
> allocation for 0 slaves in 8120ns
> I0714 15:08:44.179908 27241 slave.cpp:970] Will retry registration in
> 66.781028ms if necessary
> I0714 15:08:44.180007 27241 master.cpp:2777] Ignoring register slave message
> from slave(43)@127.0.1.1:55850 (quantal) as admission is already in progress
> I0714 15:08:44.183082 27240 leveldb.cpp:343] Persisting action (314 bytes) to
> leveldb took 16.533189ms
> I0714 15:08:44.183125 27240 replica.cpp:676] Persisted action at 3
> I0714 15:08:44.183465 27240 replica.cpp:655] Replica received learned notice
> for position 3
> I0714 15:08:44.203276 27240 leveldb.cpp:343] Persisting action (316 bytes) to
> leveldb took 19.768951ms
> I0714 15:08:44.203376 27240 replica.cpp:676] Persisted action at 3
> I0714 15:08:44.203392 27240 replica.cpp:661] Replica learned APPEND action at
> position 3
> I0714 15:08:44.204033 27240 registrar.cpp:479] Successfully updated 'registry'
> I0714 15:08:44.204138 27240 log.cpp:699] Attempting to truncate the log to 3
> I0714 15:08:44.204221 27240 master.cpp:2829] Registered slave
> 20140714-150843-16842879-55850-27216-0 at slave(43)@127.0.1.1:55850 (quantal)
> I0714 15:08:44.204241 27240 master.cpp:3975] Adding slave
> 20140714-150843-16842879-55850-27216-0 at slave(43)@127.0.1.1:55850 (quantal)
> with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0714 15:08:44.204387 27240 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0714 15:08:44.204489 27240 slave.cpp:766] Registered with master
> [email protected]:55850; given slave ID 20140714-150843-16842879-55850-27216-0
> I0714 15:08:44.204745 27240 slave.cpp:779] Checkpointing SlaveInfo to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/slave.info'
> I0714 15:08:44.204954 27240 hierarchical_allocator_process.hpp:444] Added
> slave 20140714-150843-16842879-55850-27216-0 (quantal) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0714 15:08:44.205023 27240 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 to framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.205122 27240 hierarchical_allocator_process.hpp:706] Performed
> allocation for slave 20140714-150843-16842879-55850-27216-0 in 131192ns
> I0714 15:08:44.205189 27240 slave.cpp:2323] Received ping from
> slave-observer(32)@127.0.1.1:55850
> I0714 15:08:44.205258 27240 master.hpp:801] Adding offer
> 20140714-150843-16842879-55850-27216-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 (quantal)
> I0714 15:08:44.205303 27240 master.cpp:3454] Sending 1 offers to framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.205469 27240 sched.cpp:546] Scheduler::resourceOffers took
> 23591ns
> I0714 15:08:44.206351 27241 replica.cpp:508] Replica received write request
> for position 4
> I0714 15:08:44.208353 27237 master.hpp:811] Removing offer
> 20140714-150843-16842879-55850-27216-0 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 (quantal)
> I0714 15:08:44.208436 27237 master.cpp:2133] Processing reply for offers: [
> 20140714-150843-16842879-55850-27216-0 ] on slave
> 20140714-150843-16842879-55850-27216-0 at slave(43)@127.0.1.1:55850 (quantal)
> for framework 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.208472 27237 master.cpp:2219] Authorizing framework principal
> 'test-principal' to launch task 4a6783aa-8d07-46e3-8399-2a5d047f0021 as user
> 'jenkins'
> I0714 15:08:44.208909 27237 master.hpp:773] Adding task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 (quantal)
> I0714 15:08:44.208947 27237 master.cpp:2285] Launching task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 at slave(43)@127.0.1.1:55850 (quantal)
> I0714 15:08:44.209090 27237 slave.cpp:1001] Got assigned task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 for framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.209190 27237 slave.cpp:3398] Checkpointing FrameworkInfo to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/framework.info'
> I0714 15:08:44.209413 27237 slave.cpp:3405] Checkpointing framework pid
> '[email protected]:55850' to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/framework.pid'
> I0714 15:08:44.209710 27237 slave.cpp:1111] Launching task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 for framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.210978 27237 slave.cpp:3720] Checkpointing ExecutorInfo to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/executor.info'
> I0714 15:08:44.211520 27237 slave.cpp:3835] Checkpointing TaskInfo to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/runs/19c466f8-bb5a-4842-a152-f585ff88762a/tasks/4a6783aa-8d07-46e3-8399-2a5d047f0021/task.info'
> I0714 15:08:44.211714 27237 slave.cpp:1221] Queuing task
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' for executor
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> '20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.211937 27236 containerizer.cpp:427] Starting container
> '19c466f8-bb5a-4842-a152-f585ff88762a' for executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> '20140714-150843-16842879-55850-27216-0000'
> I0714 15:08:44.212242 27236 slave.cpp:560] Successfully attached file
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/runs/19c466f8-bb5a-4842-a152-f585ff88762a'
> I0714 15:08:44.216187 27236 launcher.cpp:137] Forked child with pid '28451'
> for container '19c466f8-bb5a-4842-a152-f585ff88762a'
> I0714 15:08:44.217281 27236 containerizer.cpp:705] Checkpointing executor's
> forked pid 28451 to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/runs/19c466f8-bb5a-4842-a152-f585ff88762a/pids/forked.pid'
> I0714 15:08:44.219408 27236 containerizer.cpp:537] Fetching URIs for
> container '19c466f8-bb5a-4842-a152-f585ff88762a' using command
> '/var/jenkins/workspace/mesos-ubuntu-12.10-gcc/src/mesos-fetcher'
> I0714 15:08:44.223963 27241 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 17.554461ms
> I0714 15:08:44.224501 27241 replica.cpp:676] Persisted action at 4
> I0714 15:08:44.225051 27241 replica.cpp:655] Replica received learned notice
> for position 4
> I0714 15:08:44.242923 27241 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 17.806547ms
> I0714 15:08:44.243057 27241 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 57154ns
> I0714 15:08:44.243078 27241 replica.cpp:676] Persisted action at 4
> I0714 15:08:44.243096 27241 replica.cpp:661] Replica learned TRUNCATE action
> at position 4
> I0714 15:08:44.401140 27241 slave.cpp:2468] Monitoring executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> '20140714-150843-16842879-55850-27216-0000' in container
> '19c466f8-bb5a-4842-a152-f585ff88762a'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0714 15:08:44.434221 28486 process.cpp:1671] libprocess is initialized on
> 127.0.1.1:34669 for 8 cpus
> I0714 15:08:44.436146 28486 exec.cpp:131] Version: 0.20.0
> I0714 15:08:44.438555 28500 exec.cpp:181] Executor started at:
> executor(1)@127.0.1.1:34669 with pid 28486
> I0714 15:08:44.440846 27241 slave.cpp:1732] Got registration for executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.440917 27241 slave.cpp:1817] Checkpointing executor pid
> 'executor(1)@127.0.1.1:34669' to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/runs/19c466f8-bb5a-4842-a152-f585ff88762a/pids/libprocess.pid'
> I0714 15:08:44.442373 27243 process.cpp:1098] Socket closed while receiving
> I0714 15:08:44.442790 27241 slave.cpp:1851] Flushing queued task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 for executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.443192 27243 process.cpp:1098] Socket closed while receiving
> I0714 15:08:44.443994 28508 process.cpp:1037] Socket closed while receiving
> I0714 15:08:44.444144 28508 process.cpp:1037] Socket closed while receiving
> I0714 15:08:44.444741 28500 exec.cpp:205] Executor registered on slave
> 20140714-150843-16842879-55850-27216-0
> Registered executor on quantal
> I0714 15:08:44.446338 28500 exec.cpp:217] Executor::registered took 534236ns
> I0714 15:08:44.446715 28500 exec.cpp:292] Executor asked to run task
> '4a6783aa-8d07-46e3-8399-2a5d047f0021'
> Starting task 4a6783aa-8d07-46e3-8399-2a5d047f0021
> I0714 15:08:44.447548 28500 exec.cpp:301] Executor::launchTask took 584306ns
> sh -c 'sleep 1000'
> Forked command at 28509
> I0714 15:08:44.451202 28506 exec.cpp:524] Executor sending status update
> TASK_RUNNING (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.452327 27239 slave.cpp:2086] Handling status update
> TASK_RUNNING (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 from executor(1)@127.0.1.1:34669
> I0714 15:08:44.452503 27239 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.452520 27239 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 4a6783aa-8d07-46e3-8399-2a5d047f0021 of
> framework 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.452775 27239 status_update_manager.hpp:342] Checkpointing
> UPDATE for status update TASK_RUNNING (UUID:
> 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.472384 27239 status_update_manager.cpp:373] Forwarding status
> update TASK_RUNNING (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 to [email protected]:55850
> I0714 15:08:44.472764 27237 master.cpp:3115] Status update TASK_RUNNING
> (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 from slave
> 20140714-150843-16842879-55850-27216-0 at slave(43)@127.0.1.1:55850 (quantal)
> I0714 15:08:44.472854 27237 sched.cpp:637] Scheduler::statusUpdate took
> 17656ns
> I0714 15:08:44.472920 27237 master.cpp:2639] Forwarding status update
> acknowledgement 323fc20a-b5b8-475d-8752-b1f853797f55 for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 to slave
> 20140714-150843-16842879-55850-27216-0 at slave(43)@127.0.1.1:55850 (quantal)
> I0714 15:08:44.473122 27239 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.473146 27239 status_update_manager.hpp:342] Checkpointing ACK
> for status update TASK_RUNNING (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55)
> for task 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.473244 27237 slave.cpp:2244] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.473258 27237 slave.cpp:2250] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 323fc20a-b5b8-475d-8752-b1f853797f55) for
> task 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 to executor(1)@127.0.1.1:34669
> I0714 15:08:44.473567 27243 process.cpp:1098] Socket closed while receiving
> I0714 15:08:44.474095 28508 process.cpp:1037] Socket closed while receiving
> I0714 15:08:44.474676 28502 exec.cpp:338] Executor received status update
> acknowledgement 323fc20a-b5b8-475d-8752-b1f853797f55 for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.491111 27239 slave.cpp:1672] Status update manager
> successfully handled status update acknowledgement (UUID:
> 323fc20a-b5b8-475d-8752-b1f853797f55) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.491761 27216 slave.cpp:484] Slave terminating
> I0714 15:08:44.492559 27216 containerizer.cpp:124] Using isolation:
> posix/cpu,posix/mem
> I0714 15:08:44.494635 27237 master.cpp:766] Slave
> 20140714-150843-16842879-55850-27216-0 at slave(43)@127.0.1.1:55850 (quantal)
> disconnected
> I0714 15:08:44.494663 27237 master.cpp:1608] Disconnecting slave
> 20140714-150843-16842879-55850-27216-0
> I0714 15:08:44.495120 27237 slave.cpp:168] Slave started on
> 44)@127.0.1.1:55850
> I0714 15:08:44.495133 27237 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/credential'
> I0714 15:08:44.495226 27237 slave.cpp:266] Slave using credential for:
> test-principal
> I0714 15:08:44.495322 27237 slave.cpp:279] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0714 15:08:44.495407 27237 slave.cpp:324] Slave hostname: quantal
> I0714 15:08:44.495419 27237 slave.cpp:325] Slave checkpoint: true
> I0714 15:08:44.495939 27242 master.cpp:2469] Asked to kill task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.496207 27238 state.cpp:33] Recovering state from
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta'
> I0714 15:08:44.498291 27240 slave.cpp:3194] Recovering framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.498325 27240 slave.cpp:3570] Recovering executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.498940 27240 status_update_manager.cpp:193] Recovering status
> update manager
> I0714 15:08:44.498956 27240 status_update_manager.cpp:201] Recovering
> executor '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.498975 27240 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 4a6783aa-8d07-46e3-8399-2a5d047f0021 of
> framework 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.499092 27240 status_update_manager.hpp:306] Replaying status
> update stream for task 4a6783aa-8d07-46e3-8399-2a5d047f0021
> I0714 15:08:44.499241 27240 slave.cpp:560] Successfully attached file
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/runs/19c466f8-bb5a-4842-a152-f585ff88762a'
> I0714 15:08:44.499433 27240 containerizer.cpp:287] Recovering containerizer
> I0714 15:08:44.499457 27240 containerizer.cpp:329] Recovering container
> '19c466f8-bb5a-4842-a152-f585ff88762a' for executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.495811 27237 hierarchical_allocator_process.hpp:483] Slave
> 20140714-150843-16842879-55850-27216-0 disconnected
> I0714 15:08:44.501255 27240 slave.cpp:3067] Sending reconnect request to
> executor 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 at executor(1)@127.0.1.1:34669
> I0714 15:08:44.502030 28501 exec.cpp:251] Received reconnect request from
> slave 20140714-150843-16842879-55850-27216-0
> I0714 15:08:44.502627 27243 process.cpp:1098] Socket closed while receiving
> I0714 15:08:44.502681 28508 process.cpp:1037] Socket closed while receiving
> I0714 15:08:44.503211 27240 slave.cpp:1911] Re-registering executor
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:44.504238 28501 exec.cpp:228] Executor re-registered on slave
> 20140714-150843-16842879-55850-27216-0
> I0714 15:08:44.505033 28501 exec.cpp:240] Executor::reregistered took 45053ns
> Re-registered executor on quantal
> I0714 15:08:44.505507 27243 process.cpp:1098] Socket closed while receiving
> I0714 15:08:44.505558 28508 process.cpp:1037] Socket closed while receiving
> I0714 15:08:44.948043 27241 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 124255ns
> I0714 15:08:45.948671 27237 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 61521ns
> I0714 15:08:46.503978 27238 slave.cpp:2035] Cleaning up un-reregistered
> executors
> I0714 15:08:46.504050 27238 slave.cpp:3126] Finished recovery
> I0714 15:08:46.504590 27238 slave.cpp:599] New master detected at
> [email protected]:55850
> I0714 15:08:46.504639 27238 slave.cpp:675] Authenticating with master
> [email protected]:55850
> I0714 15:08:46.504729 27238 slave.cpp:648] Detecting new master
> I0714 15:08:46.504772 27238 status_update_manager.cpp:167] New master
> detected at [email protected]:55850
> I0714 15:08:46.504863 27238 authenticatee.hpp:128] Creating new client SASL
> connection
> I0714 15:08:46.505091 27238 master.cpp:3507] Authenticating
> slave(44)@127.0.1.1:55850
> I0714 15:08:46.505239 27238 authenticator.hpp:156] Creating new server SASL
> connection
> I0714 15:08:46.505363 27238 authenticatee.hpp:219] Received SASL
> authentication mechanisms: CRAM-MD5
> I0714 15:08:46.505393 27238 authenticatee.hpp:245] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0714 15:08:46.505420 27238 authenticator.hpp:262] Received SASL
> authentication start
> I0714 15:08:46.505476 27238 authenticator.hpp:384] Authentication requires
> more steps
> I0714 15:08:46.505506 27238 authenticatee.hpp:265] Received SASL
> authentication step
> I0714 15:08:46.505542 27238 authenticator.hpp:290] Received SASL
> authentication step
> I0714 15:08:46.505558 27238 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0714 15:08:46.505566 27238 auxprop.cpp:153] Looking up auxiliary property
> '*userPassword'
> I0714 15:08:46.505584 27238 auxprop.cpp:153] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0714 15:08:46.505595 27238 auxprop.cpp:81] Request to lookup properties for
> user: 'test-principal' realm: 'quantal' server FQDN: 'quantal'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0714 15:08:46.505601 27238 auxprop.cpp:103] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0714 15:08:46.505606 27238 auxprop.cpp:103] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0714 15:08:46.505616 27238 authenticator.hpp:376] Authentication success
> I0714 15:08:46.505646 27238 authenticatee.hpp:305] Authentication success
> I0714 15:08:46.505671 27238 master.cpp:3547] Successfully authenticated
> principal 'test-principal' at slave(44)@127.0.1.1:55850
> I0714 15:08:46.505769 27238 slave.cpp:732] Successfully authenticated with
> master [email protected]:55850
> I0714 15:08:46.505873 27238 slave.cpp:970] Will retry registration in
> 17.903094ms if necessary
> W0714 15:08:46.505991 27238 master.cpp:2904] Slave at
> slave(44)@127.0.1.1:55850 (quantal) is being allowed to re-register with an
> already in use id (20140714-150843-16842879-55850-27216-0)
> W0714 15:08:46.506063 27238 master.cpp:3679] Slave
> 20140714-150843-16842879-55850-27216-0 at slave(44)@127.0.1.1:55850 (quantal)
> has non-terminal task 4a6783aa-8d07-46e3-8399-2a5d047f0021 that is supposed
> to be killed. Killing it now!
> I0714 15:08:46.506150 27238 slave.cpp:816] Re-registered with master
> [email protected]:55850
> I0714 15:08:46.506186 27238 slave.cpp:1277] Asked to kill task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.507275 27241 hierarchical_allocator_process.hpp:497] Slave
> 20140714-150843-16842879-55850-27216-0 reconnected
> I0714 15:08:46.508061 28504 exec.cpp:312] Executor asked to kill task
> '4a6783aa-8d07-46e3-8399-2a5d047f0021'
> I0714 15:08:46.508117 28504 exec.cpp:321] Executor::killTask took 24954ns
> Shutting down
> Sending SIGTERM to process tree at pid 28509
> I0714 15:08:46.512238 27243 process.cpp:1098] Socket closed while receiving
> I0714 15:08:46.512508 27238 slave.cpp:1582] Updating framework
> 20140714-150843-16842879-55850-27216-0000 pid to
> [email protected]:55850
> I0714 15:08:46.512846 27238 slave.cpp:1590] Checkpointing framework pid
> '[email protected]:55850' to
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/framework.pid'
> I0714 15:08:46.513419 28508 process.cpp:1037] Socket closed while receiving
> Killing the following process trees:
> [
> -+- 28509 sh -c sleep 1000
> \--- 28510 sleep 1000
> ]
> Command terminated with signal Terminated (pid: 28509)
> I0714 15:08:46.940232 28506 exec.cpp:524] Executor sending status update
> TASK_KILLED (UUID: e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.940918 27240 slave.cpp:2086] Handling status update
> TASK_KILLED (UUID: e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 from executor(1)@127.0.1.1:34669
> I0714 15:08:46.940979 27240 slave.cpp:3768] Terminating task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021
> I0714 15:08:46.941603 27240 status_update_manager.cpp:320] Received status
> update TASK_KILLED (UUID: e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.941644 27240 status_update_manager.hpp:342] Checkpointing
> UPDATE for status update TASK_KILLED (UUID:
> e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.949417 27236 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 63926ns
> I0714 15:08:46.965200 27240 status_update_manager.cpp:373] Forwarding status
> update TASK_KILLED (UUID: e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 to [email protected]:55850
> I0714 15:08:46.965625 27239 master.cpp:3115] Status update TASK_KILLED (UUID:
> e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 from slave
> 20140714-150843-16842879-55850-27216-0 at slave(44)@127.0.1.1:55850 (quantal)
> I0714 15:08:46.965724 27239 master.hpp:791] Removing task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 (quantal)
> I0714 15:08:46.965903 27239 sched.cpp:637] Scheduler::statusUpdate took
> 39326ns
> I0714 15:08:46.966022 27239 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 20140714-150843-16842879-55850-27216-0 from framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.966120 27239 master.cpp:2639] Forwarding status update
> acknowledgement e3a5f8fd-eefc-42c6-94a7-086c93c01968 for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 to slave
> 20140714-150843-16842879-55850-27216-0 at slave(44)@127.0.1.1:55850 (quantal)
> I0714 15:08:46.966501 27241 slave.cpp:2244] Status update manager
> successfully handled status update TASK_KILLED (UUID:
> e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.966519 27241 slave.cpp:2250] Sending acknowledgement for
> status update TASK_KILLED (UUID: e3a5f8fd-eefc-42c6-94a7-086c93c01968) for
> task 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000 to executor(1)@127.0.1.1:34669
> I0714 15:08:46.966754 27240 status_update_manager.cpp:398] Received status
> update acknowledgement (UUID: e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.966785 27240 status_update_manager.hpp:342] Checkpointing ACK
> for status update TASK_KILLED (UUID: e3a5f8fd-eefc-42c6-94a7-086c93c01968)
> for task 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.967386 28500 exec.cpp:338] Executor received status update
> acknowledgement e3a5f8fd-eefc-42c6-94a7-086c93c01968 for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.967562 27243 process.cpp:1098] Socket closed while receiving
> I0714 15:08:46.968147 28508 process.cpp:1037] Socket closed while receiving
> I0714 15:08:46.984608 27240 status_update_manager.cpp:530] Cleaning up status
> update stream for task 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.985239 27236 slave.cpp:1672] Status update manager
> successfully handled status update acknowledgement (UUID:
> e3a5f8fd-eefc-42c6-94a7-086c93c01968) for task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021 of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:46.985280 27236 slave.cpp:3810] Completing task
> 4a6783aa-8d07-46e3-8399-2a5d047f0021
> I0714 15:08:47.940703 27243 process.cpp:1037] Socket closed while receiving
> I0714 15:08:47.940984 27238 containerizer.cpp:1019] Executor for container
> '19c466f8-bb5a-4842-a152-f585ff88762a' has exited
> I0714 15:08:47.941007 27238 containerizer.cpp:903] Destroying container
> '19c466f8-bb5a-4842-a152-f585ff88762a'
> I0714 15:08:47.950192 27241 hierarchical_allocator_process.hpp:750] Offering
> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 to framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:47.950405 27241 hierarchical_allocator_process.hpp:686] Performed
> allocation for 1 slaves in 320604ns
> I0714 15:08:47.950518 27241 master.hpp:801] Adding offer
> 20140714-150843-16842879-55850-27216-1 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 (quantal)
> I0714 15:08:47.950572 27241 master.cpp:3454] Sending 1 offers to framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:47.950774 27241 sched.cpp:546] Scheduler::resourceOffers took
> 37944ns
> I0714 15:08:47.951179 27216 master.cpp:625] Master terminating
> I0714 15:08:47.951263 27216 master.hpp:811] Removing offer
> 20140714-150843-16842879-55850-27216-1 with resources cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] on slave
> 20140714-150843-16842879-55850-27216-0 (quantal)
> I0714 15:08:47.953447 27242 sched.cpp:747] Stopping framework
> '20140714-150843-16842879-55850-27216-0000'
> I0714 15:08:47.953547 27242 slave.cpp:2330] [email protected]:55850 exited
> W0714 15:08:47.953567 27242 slave.cpp:2333] Master disconnected! Waiting for
> a new master to be elected
> I0714 15:08:47.964512 27238 slave.cpp:2526] Executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> 20140714-150843-16842879-55850-27216-0000 exited with status 0
> I0714 15:08:47.968690 27238 slave.cpp:2660] Cleaning up executor
> '4a6783aa-8d07-46e3-8399-2a5d047f0021' of framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:47.969348 27236 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/runs/19c466f8-bb5a-4842-a152-f585ff88762a'
> for gc 6.99998878298667days in the future
> I0714 15:08:47.969751 27241 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021'
> for gc 6.99998877682963days in the future
> I0714 15:08:47.970082 27239 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021/runs/19c466f8-bb5a-4842-a152-f585ff88762a'
> for gc 6.99998877336889days in the future
> I0714 15:08:47.970379 27242 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000/executors/4a6783aa-8d07-46e3-8399-2a5d047f0021'
> for gc 6.99998876968889days in the future
> I0714 15:08:47.970587 27238 slave.cpp:2735] Cleaning up framework
> 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:47.970960 27237 status_update_manager.cpp:282] Closing status
> update streams for framework 20140714-150843-16842879-55850-27216-0000
> I0714 15:08:47.971225 27236 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000'
> for gc 6.99998875966519days in the future
> I0714 15:08:47.971549 27241 gc.cpp:56] Scheduling
> '/tmp/SlaveRecoveryTest_0_ReconcileKillTask_Zl9DUt/meta/slaves/20140714-150843-16842879-55850-27216-0/frameworks/20140714-150843-16842879-55850-27216-0000'
> for gc 6.99998875612148days in the future
> W0714 15:08:47.975971 27235 containerizer.cpp:893] Ignoring destroy of
> unknown container: 19c466f8-bb5a-4842-a152-f585ff88762a
> ./tests/cluster.hpp:530: Failure
> (wait).failure(): Unknown container: 19c466f8-bb5a-4842-a152-f585ff88762a
> #
> # A fatal error has been detected by the Java Runtime Environment:
> #
> # SIGSEGV (0xb) at pc=0x00000000005a0299, pid=27216, tid=47907931709760
> #
> # JRE version: OpenJDK Runtime Environment (7.0_55-b14) (build 1.7.0_55-b14)
> # Java VM: OpenJDK 64-Bit Server VM (24.51-b03 mixed mode linux-amd64
> compressed oops)
> # Problematic frame:
> # C [lt-mesos-tests+0x1a0299] mlock@@GLIBC_2.2.5+0x1a0299
> #
> # Failed to write core dump. Core dumps have been disabled. To enable core
> dumping, try "ulimit -c unlimited" before starting Java again
> #
> # An error report file with more information is saved as:
> # /var/jenkins/workspace/mesos-ubuntu-12.10-gcc/src/hs_err_pid27216.log
> #
> # If you would like to submit a bug report, please include
> # instructions on how to reproduce the bug and visit:
> # http://icedtea.classpath.org/bugzilla
> # The crash happened outside the Java Virtual Machine in native code.
> # See problematic frame for where to report the bug.
> #
> make[3]: *** [check-local] Aborted
> make[3]: Leaving directory `/var/jenkins/workspace/mesos-ubuntu-12.10-gcc/src'
> make[2]: *** [check-am] Error 2
> make[2]: Leaving directory `/var/jenkins/workspace/mesos-ubuntu-12.10-gcc/src'
> make[1]: *** [check] Error 2
> make[1]: Leaving directory `/var/jenkins/workspace/mesos-ubuntu-12.10-gcc/src'
> make: *** [check-recursive] Error 1
> Build step 'Execute shell' marked build as failure
> erreicht: 1854109
> Sending e-mails to: [email protected] [email protected]
> Finished: FAILURE
> Help us localize this page Page generated: Jul 14, 2014 5:57:17 PMREST
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
