You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/08/07 19:30:38 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2301
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2301/changes>
Changes:
[yujie.jay] Fixed a bug in slave when launching container.
------------------------------------------
[...truncated 25049 lines...]
I0807 17:30:36.786521 690 authenticator.hpp:156] Creating new server SASL connection
I0807 17:30:36.786612 690 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0807 17:30:36.786628 690 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0807 17:30:36.786650 690 authenticator.hpp:262] Received SASL authentication start
I0807 17:30:36.786680 690 authenticator.hpp:384] Authentication requires more steps
I0807 17:30:36.786705 690 authenticatee.hpp:265] Received SASL authentication step
I0807 17:30:36.786734 690 authenticator.hpp:290] Received SASL authentication step
I0807 17:30:36.786748 690 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0807 17:30:36.786754 690 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0807 17:30:36.786763 690 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0807 17:30:36.786772 690 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0807 17:30:36.786777 690 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0807 17:30:36.786782 690 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0807 17:30:36.786792 690 authenticator.hpp:376] Authentication success
I0807 17:30:36.786814 690 authenticatee.hpp:305] Authentication success
I0807 17:30:36.786835 690 master.cpp:3645] Successfully authenticated principal 'test-principal' at slave(78)@140.211.11.27:53862
I0807 17:30:36.786896 690 slave.cpp:720] Successfully authenticated with master master@140.211.11.27:53862
I0807 17:30:36.786928 690 slave.cpp:971] Will retry registration in 12.118386ms if necessary
I0807 17:30:36.786988 690 master.cpp:2827] Registering slave at slave(78)@140.211.11.27:53862 (hemera.apache.org) with id 20140807-173036-453759884-53862-403-0
I0807 17:30:36.787086 690 registrar.cpp:422] Attempting to update the 'registry'
I0807 17:30:36.788794 690 log.cpp:680] Attempting to append 328 bytes to the log
I0807 17:30:36.788843 690 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0807 17:30:36.789048 403 sched.cpp:139] Version: 0.20.0
I0807 17:30:36.789103 690 replica.cpp:508] Replica received write request for position 3
I0807 17:30:36.789425 694 sched.cpp:235] New master detected at master@140.211.11.27:53862
I0807 17:30:36.789446 694 sched.cpp:285] Authenticating with master master@140.211.11.27:53862
I0807 17:30:36.789535 694 authenticatee.hpp:128] Creating new client SASL connection
I0807 17:30:36.789729 714 master.cpp:3605] Authenticating scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862
I0807 17:30:36.789819 714 authenticator.hpp:156] Creating new server SASL connection
I0807 17:30:36.789908 714 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0807 17:30:36.789923 714 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0807 17:30:36.789948 714 authenticator.hpp:262] Received SASL authentication start
I0807 17:30:36.789985 714 authenticator.hpp:384] Authentication requires more steps
I0807 17:30:36.790009 714 authenticatee.hpp:265] Received SASL authentication step
I0807 17:30:36.790040 714 authenticator.hpp:290] Received SASL authentication step
I0807 17:30:36.790053 714 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0807 17:30:36.790060 714 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0807 17:30:36.790069 714 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0807 17:30:36.790078 714 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0807 17:30:36.790084 714 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0807 17:30:36.790089 714 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0807 17:30:36.790101 714 authenticator.hpp:376] Authentication success
I0807 17:30:36.790124 714 authenticatee.hpp:305] Authentication success
I0807 17:30:36.790144 714 master.cpp:3645] Successfully authenticated principal 'test-principal' at scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862
I0807 17:30:36.790210 714 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:53862
I0807 17:30:36.790220 714 sched.cpp:478] Sending registration request to master@140.211.11.27:53862
I0807 17:30:36.790261 714 master.cpp:1305] Received registration request from scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862
I0807 17:30:36.790278 714 master.cpp:1265] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0807 17:30:36.790380 714 master.cpp:1364] Registering framework 20140807-173036-453759884-53862-403-0000 at scheduler-64da95a6-74b8-438f-b973-b9de8c8351fe@140.211.11.27:53862
I0807 17:30:36.790473 714 sched.cpp:409] Framework registered with 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.790493 714 sched.cpp:423] Scheduler::registered took 9519ns
I0807 17:30:36.790526 714 hierarchical_allocator_process.hpp:326] Added framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.790534 714 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0807 17:30:36.790539 714 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 5946ns
I0807 17:30:36.805169 694 slave.cpp:971] Will retry registration in 12.417387ms if necessary
I0807 17:30:36.805233 694 master.cpp:2815] Ignoring register slave message from slave(78)@140.211.11.27:53862 (hemera.apache.org) as admission is already in progress
I0807 17:30:36.805675 690 leveldb.cpp:343] Persisting action (347 bytes) to leveldb took 16.495309ms
I0807 17:30:36.805701 690 replica.cpp:676] Persisted action at 3
I0807 17:30:36.805896 690 replica.cpp:655] Replica received learned notice for position 3
I0807 17:30:36.821661 690 leveldb.cpp:343] Persisting action (349 bytes) to leveldb took 15.749773ms
I0807 17:30:36.821760 690 replica.cpp:676] Persisted action at 3
I0807 17:30:36.821801 671 slave.cpp:971] Will retry registration in 17.196934ms if necessary
I0807 17:30:36.821817 690 replica.cpp:661] Replica learned APPEND action at position 3
I0807 17:30:36.821873 671 master.cpp:2815] Ignoring register slave message from slave(78)@140.211.11.27:53862 (hemera.apache.org) as admission is already in progress
I0807 17:30:36.822265 709 registrar.cpp:479] Successfully updated 'registry'
I0807 17:30:36.822342 694 log.cpp:699] Attempting to truncate the log to 3
I0807 17:30:36.822438 709 master.cpp:2867] Registered slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org)
I0807 17:30:36.822453 694 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0807 17:30:36.822455 709 master.cpp:4078] Adding slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0807 17:30:36.822751 694 slave.cpp:754] Registered with master master@140.211.11.27:53862; given slave ID 20140807-173036-453759884-53862-403-0
I0807 17:30:36.822796 694 slave.cpp:2324] Received ping from slave-observer(69)@140.211.11.27:53862
I0807 17:30:36.822898 709 hierarchical_allocator_process.hpp:439] Added slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0807 17:30:36.822968 709 hierarchical_allocator_process.hpp:714] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 to framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.823096 709 hierarchical_allocator_process.hpp:670] Performed allocation for slave 20140807-173036-453759884-53862-403-0 in 157195ns
I0807 17:30:36.823163 709 master.hpp:847] Adding offer 20140807-173036-453759884-53862-403-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org)
I0807 17:30:36.823220 709 master.cpp:3552] Sending 1 offers to framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.823344 709 sched.cpp:546] Scheduler::resourceOffers took 25958ns
I0807 17:30:36.823503 692 replica.cpp:508] Replica received write request for position 4
I0807 17:30:36.827436 709 master.hpp:857] Removing offer 20140807-173036-453759884-53862-403-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org)
I0807 17:30:36.827512 709 master.cpp:2189] Processing reply for offers: [ 20140807-173036-453759884-53862-403-0 ] on slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org) for framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.827560 709 master.cpp:2275] Authorizing framework principal 'test-principal' to launch task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a as user 'jenkins'
I0807 17:30:36.827962 709 master.hpp:819] Adding task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org)
I0807 17:30:36.828006 709 master.cpp:2341] Launching task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org)
I0807 17:30:36.828172 709 slave.cpp:1002] Got assigned task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a for framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.828387 709 slave.cpp:1112] Launching task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a for framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.831197 709 exec.cpp:131] Version: 0.20.0
I0807 17:30:36.831306 709 slave.cpp:1222] Queuing task '81c584a6-2ff3-4e65-b99f-8a7a37c3421a' for executor default of framework '20140807-173036-453759884-53862-403-0000
I0807 17:30:36.831377 709 slave.cpp:2515] Monitoring executor 'default' of framework '20140807-173036-453759884-53862-403-0000' in container 'aa9ed10a-024d-456f-bac4-18c385b9aa01'
I0807 17:30:36.831487 709 exec.cpp:181] Executor started at: executor(28)@140.211.11.27:53862 with pid 403
I0807 17:30:36.831568 709 slave.cpp:543] Successfully attached file '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_I9q9iQ/slaves/20140807-173036-453759884-53862-403-0/frameworks/20140807-173036-453759884-53862-403-0000/executors/default/runs/aa9ed10a-024d-456f-bac4-18c385b9aa01'
I0807 17:30:36.831601 709 slave.cpp:1733] Got registration for executor 'default' of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.831707 709 slave.cpp:1852] Flushing queued task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a for executor 'default' of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.831787 709 exec.cpp:205] Executor registered on slave 20140807-173036-453759884-53862-403-0
I0807 17:30:36.833026 709 exec.cpp:217] Executor::registered took 17155ns
I0807 17:30:36.833096 709 exec.cpp:292] Executor asked to run task '81c584a6-2ff3-4e65-b99f-8a7a37c3421a'
I0807 17:30:36.833132 709 exec.cpp:301] Executor::launchTask took 24849ns
I0807 17:30:36.834453 709 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.834625 709 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 from executor(28)@140.211.11.27:53862
I0807 17:30:36.834779 709 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.834857 709 status_update_manager.cpp:499] Creating StatusUpdate stream for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.835022 709 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to master@140.211.11.27:53862
I0807 17:30:36.835211 709 master.cpp:3196] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.835320 709 master.cpp:3162] Status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 from slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org)
I0807 17:30:36.835427 709 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.835505 709 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to executor(28)@140.211.11.27:53862
I0807 17:30:36.835656 709 sched.cpp:637] Scheduler::statusUpdate took 15224ns
I0807 17:30:36.835770 709 exec.cpp:338] Executor received status update acknowledgement dcc58d11-5209-4672-b0f2-cacf58fe2fe7 for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.835892 709 master.cpp:2677] Forwarding status update acknowledgement dcc58d11-5209-4672-b0f2-cacf58fe2fe7 for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org)
I0807 17:30:36.837323 692 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.801156ms
I0807 17:30:36.837348 692 replica.cpp:676] Persisted action at 4
I0807 17:30:36.837560 692 replica.cpp:655] Replica received learned notice for position 4
I0807 17:30:36.857661 692 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 20.085146ms
I0807 17:30:36.857754 692 leveldb.cpp:401] Deleting ~2 keys from leveldb took 24526ns
I0807 17:30:36.857765 692 replica.cpp:676] Persisted action at 4
I0807 17:30:36.857774 692 replica.cpp:661] Replica learned TRUNCATE action at position 4
W0807 17:30:36.877737 692 slave.cpp:1640] Ignoring status update acknowledgement message from master@127.0.0.1:1 because it is not the expected master: master@140.211.11.27:53862
I0807 17:30:36.889756 677 hierarchical_allocator_process.hpp:650] Performed allocation for 1 slaves in 30199ns
I0807 17:30:36.889976 677 master.cpp:120] No whitelist given. Advertising offers for all slaves
W0807 17:30:36.890019 677 status_update_manager.cpp:477] Resending status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.890033 677 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to master@140.211.11.27:53862
I0807 17:30:36.890148 677 master.cpp:3196] Forwarding status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.890182 677 master.cpp:3162] Status update TASK_RUNNING (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 from slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org)
I0807 17:30:36.890244 677 sched.cpp:637] Scheduler::statusUpdate took 11012ns
I0807 17:30:36.890286 677 master.cpp:2677] Forwarding status update acknowledgement dcc58d11-5209-4672-b0f2-cacf58fe2fe7 for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 to slave 20140807-173036-453759884-53862-403-0 at slave(78)@140.211.11.27:53862 (hemera.apache.org)
I0807 17:30:36.890352 677 status_update_manager.cpp:398] Received status update acknowledgement (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.890404 677 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: dcc58d11-5209-4672-b0f2-cacf58fe2fe7) for task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.921783 403 master.cpp:634] Master terminating
I0807 17:30:36.921882 403 master.hpp:837] Removing task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140807-173036-453759884-53862-403-0 (hemera.apache.org)
W0807 17:30:36.921967 403 master.cpp:4371] Removing task 81c584a6-2ff3-4e65-b99f-8a7a37c3421a of framework 20140807-173036-453759884-53862-403-0000 and slave 20140807-173036-453759884-53862-403-0 in non-terminal state TASK_RUNNING
I0807 17:30:36.923032 403 slave.cpp:466] Slave terminating
I0807 17:30:36.923048 403 slave.cpp:1406] Asked to shut down framework 20140807-173036-453759884-53862-403-0000 by @0.0.0.0:0
I0807 17:30:36.923061 403 slave.cpp:1431] Shutting down framework 20140807-173036-453759884-53862-403-0000
I0807 17:30:36.923074 403 slave.cpp:2855] Shutting down executor 'default' of framework 20140807-173036-453759884-53862-403-0000
[ OK ] SlaveTest.IgnoreNonLeaderStatusUpdateAcknowledgement (400 ms)
[----------] 9 tests from SlaveTest (8449 ms total)
[----------] 6 tests from RateLimitingTest
[ RUN ] RateLimitingTest.DifferentPrincipalFrameworks
Using temporary directory '/tmp/RateLimitingTest_DifferentPrincipalFrameworks_B7fkoR'
I0807 17:30:36.985301 403 leveldb.cpp:176] Opened db in 60.744149ms
I0807 17:30:37.017660 403 leveldb.cpp:183] Compacted db in 32.311501ms
I0807 17:30:37.017698 403 leveldb.cpp:198] Created db iterator in 3962ns
I0807 17:30:37.017705 403 leveldb.cpp:204] Seeked to beginning of db in 780ns
I0807 17:30:37.017711 403 leveldb.cpp:273] Iterated through 0 keys in the db in 262ns
I0807 17:30:37.017727 403 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0807 17:30:37.022848 690 master.cpp:286] Master 20140807-173037-453759884-53862-403 (hemera.apache.org) started on 140.211.11.27:53862
I0807 17:30:37.022877 690 master.cpp:325] Master allowing unauthenticated frameworks to register
I0807 17:30:37.022883 690 master.cpp:328] Master only allowing authenticated slaves to register
I0807 17:30:37.022891 690 credentials.hpp:36] Loading credentials for authentication from '/tmp/RateLimitingTest_DifferentPrincipalFrameworks_B7fkoR/credentials'
I0807 17:30:37.023021 690 master.cpp:357] Authorization enabled
I0807 17:30:37.023068 690 master.cpp:404] Framework rate limiting enabled
I0807 17:30:37.023520 690 recover.cpp:425] Starting replica recovery
I0807 17:30:37.023797 690 hierarchical_allocator_process.hpp:296] Initializing hierarchical allocator process with master : master@140.211.11.27:53862
I0807 17:30:37.023833 690 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0807 17:30:37.023905 690 master.cpp:1186] The newly elected leader is master@140.211.11.27:53862 with id 20140807-173037-453759884-53862-403
I0807 17:30:37.023916 690 master.cpp:1199] Elected as the leading master!
I0807 17:30:37.023921 690 master.cpp:1017] Recovering from registrar
I0807 17:30:37.023972 690 recover.cpp:451] Replica is in EMPTY status
I0807 17:30:37.024025 690 registrar.cpp:313] Recovering registrar
I0807 17:30:37.024520 690 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0807 17:30:37.024587 690 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0807 17:30:37.024698 690 recover.cpp:542] Updating replica status to STARTING
I0807 17:30:37.041659 690 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.898675ms
I0807 17:30:37.041756 690 replica.cpp:320] Persisted replica status to STARTING
I0807 17:30:37.041893 690 recover.cpp:451] Replica is in STARTING status
I0807 17:30:37.042265 690 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0807 17:30:37.042394 690 recover.cpp:188] Received a recover response from a replica in STARTING status
I0807 17:30:37.042675 711 recover.cpp:542] Updating replica status to VOTING
I0807 17:30:37.057548 677 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.812382ms
I0807 17:30:37.057584 677 replica.cpp:320] Persisted replica status to VOTING
I0807 17:30:37.057652 677 recover.cpp:556] Successfully joined the Paxos group
I0807 17:30:37.057731 677 recover.cpp:440] Recover process terminated
I0807 17:30:37.057884 684 log.cpp:656] Attempting to start the writer
I0807 17:30:37.058269 684 replica.cpp:474] Replica received implicit promise request with proposal 1
I0807 17:30:37.073742 684 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 15.458383ms
I0807 17:30:37.073770 684 replica.cpp:342] Persisted promised to 1
I0807 17:30:37.074256 701 coordinator.cpp:230] Coordinator attemping to fill missing position
I0807 17:30:37.075018 691 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0807 17:30:37.089825 691 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 14.783082ms
I0807 17:30:37.089853 691 replica.cpp:676] Persisted action at 0
I0807 17:30:37.090317 694 replica.cpp:508] Replica received write request for position 0
I0807 17:30:37.090348 694 leveldb.cpp:438] Reading position from leveldb took 13689ns
I0807 17:30:37.105913 694 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 15.549578ms
I0807 17:30:37.105942 694 replica.cpp:676] Persisted action at 0
I0807 17:30:37.106113 694 replica.cpp:655] Replica received learned notice for position 0
I0807 17:30:37.121995 694 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.864808ms
I0807 17:30:37.122022 694 replica.cpp:676] Persisted action at 0
I0807 17:30:37.122031 694 replica.cpp:661] Replica learned NOP action at position 0
I0807 17:30:37.122241 694 log.cpp:672] Writer started with ending position 0
I0807 17:30:37.122505 694 leveldb.cpp:438] Reading position from leveldb took 11851ns
I0807 17:30:37.124013 694 registrar.cpp:346] Successfully fetched the registry (0B)
I0807 17:30:37.124034 694 registrar.cpp:422] Attempting to update the 'registry'
I0807 17:30:37.125591 694 log.cpp:680] Attempting to append 136 bytes to the log
I0807 17:30:37.125651 694 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0807 17:30:37.125869 694 replica.cpp:508] Replica received write request for position 1
I0807 17:30:37.142525 694 leveldb.cpp:343] Persisting action (155 bytes) to leveldb took 16.640654ms
I0807 17:30:37.142551 694 replica.cpp:676] Persisted action at 1
I0807 17:30:37.153822 714 replica.cpp:655] Replica received learned notice for position 1
I0807 17:30:37.173665 714 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 19.756436ms
I0807 17:30:37.173753 714 replica.cpp:676] Persisted action at 1
I0807 17:30:37.173810 714 replica.cpp:661] Replica learned APPEND action at position 1
I0807 17:30:37.174188 714 registrar.cpp:479] Successfully updated 'registry'
I0807 17:30:37.174279 714 registrar.cpp:372] Successfully recovered registrar
I0807 17:30:37.174371 714 log.cpp:699] Attempting to truncate the log to 1
I0807 17:30:37.174497 714 master.cpp:1044] Recovered 0 slaves from the Registry (98B) ; allowing 10mins for slaves to re-register
I0807 17:30:37.174588 714 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0807 17:30:37.175026 667 replica.cpp:508] Replica received write request for position 2
I0807 17:30:37.190742 667 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.687275ms
I0807 17:30:37.190770 667 replica.cpp:676] Persisted action at 2
I0807 17:30:37.190974 667 replica.cpp:655] Replica received learned notice for position 2
I0807 17:30:37.210861 667 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 19.869691ms
I0807 17:30:37.210911 667 leveldb.cpp:401] Deleting ~1 keys from leveldb took 18729ns
I0807 17:30:37.210922 667 replica.cpp:676] Persisted action at 2
I0807 17:30:37.210932 667 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0807 17:30:37.228948 403 sched.cpp:139] Version: 0.20.0
I0807 17:30:37.229142 694 sched.cpp:235] New master detected at master@140.211.11.27:53862
I0807 17:30:37.229174 694 sched.cpp:243] No credentials provided. Attempting to register without authentication
I0807 17:30:37.229182 694 sched.cpp:478] Sending registration request to master@140.211.11.27:53862
I0807 17:30:37.241777 714 master.cpp:1305] Received registration request from scheduler-4f26e506-1c7a-4985-87f5-e7a0b260a2ff@140.211.11.27:53862
I0807 17:30:37.241812 714 master.cpp:1265] Authorizing framework principal 'framework1' to receive offers for role '*'
I0807 17:30:37.241943 714 master.cpp:1364] Registering framework 20140807-173037-453759884-53862-403-0000 at scheduler-4f26e506-1c7a-4985-87f5-e7a0b260a2ff@140.211.11.27:53862
I0807 17:30:37.242048 714 sched.cpp:409] Framework registered with 20140807-173037-453759884-53862-403-0000
I0807 17:30:37.242069 714 sched.cpp:423] Scheduler::registered took 10298ns
I0807 17:30:37.242105 714 hierarchical_allocator_process.hpp:326] Added framework 20140807-173037-453759884-53862-403-0000
I0807 17:30:37.242112 714 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0807 17:30:37.242117 714 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 6166ns
I0807 17:30:37.264605 403 sched.cpp:139] Version: 0.20.0
I0807 17:30:37.264735 699 sched.cpp:235] New master detected at master@140.211.11.27:53862
I0807 17:30:37.264753 699 sched.cpp:243] No credentials provided. Attempting to register without authentication
I0807 17:30:37.264760 699 sched.cpp:478] Sending registration request to master@140.211.11.27:53862
I0807 17:30:37.264834 699 master.cpp:1305] Received registration request from scheduler-a7479512-9f16-4147-9947-f3f5236a55f5@140.211.11.27:53862
I0807 17:30:37.264853 699 master.cpp:1265] Authorizing framework principal 'framework2' to receive offers for role '*'
I0807 17:30:37.264996 699 master.cpp:1364] Registering framework 20140807-173037-453759884-53862-403-0001 at scheduler-a7479512-9f16-4147-9947-f3f5236a55f5@140.211.11.27:53862
I0807 17:30:37.265086 699 sched.cpp:409] Framework registered with 20140807-173037-453759884-53862-403-0001
I0807 17:30:37.265105 699 sched.cpp:423] Scheduler::registered took 8957ns
I0807 17:30:37.265137 699 hierarchical_allocator_process.hpp:326] Added framework 20140807-173037-453759884-53862-403-0001
I0807 17:30:37.265146 699 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0807 17:30:37.265151 699 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 5654ns
I0807 17:30:37.285781 699 master.cpp:1305] Received registration request from scheduler-4f26e506-1c7a-4985-87f5-e7a0b260a2ff@140.211.11.27:53862
I0807 17:30:37.285807 699 master.cpp:1265] Authorizing framework principal 'framework1' to receive offers for role '*'
lt-mesos-tests: ../../3rdparty/libprocess/3rdparty/stout/include/stout/option.hpp:104: const T& Option<T>::get() const [with T = process::Owned<mesos::internal::master::Master::BoundedRateLimiter>]: Assertion `state == SOME' failed.
make[3]: *** [check-local] Aborted (core dumped)
make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make[1]: *** [check] Error 2
make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make: *** [check-recursive] Error 1
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal :
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2305
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2305/changes>
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2304
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2304/changes>
Changes:
[vinodkone] Temporarily disabled HealthcheckTest.ConsecutiveFailures test due to
------------------------------------------
[...truncated 57278 lines...]
I0808 07:47:21.594179 14231 authenticator.hpp:376] Authentication success
I0808 07:47:21.594202 14231 authenticatee.hpp:305] Authentication success
I0808 07:47:21.594223 14231 master.cpp:3655] Successfully authenticated principal 'test-principal' at scheduler-631ca56b-b23d-4494-8cc8-bcdf6e0533ee@140.211.11.27:54672
I0808 07:47:21.594280 14231 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:54672
I0808 07:47:21.594292 14231 sched.cpp:478] Sending registration request to master@140.211.11.27:54672
I0808 07:47:21.594332 14231 master.cpp:1315] Received registration request from scheduler-631ca56b-b23d-4494-8cc8-bcdf6e0533ee@140.211.11.27:54672
I0808 07:47:21.594349 14231 master.cpp:1275] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0808 07:47:21.594458 14231 master.cpp:1374] Registering framework 20140808-074721-453759884-54672-13998-0000 at scheduler-631ca56b-b23d-4494-8cc8-bcdf6e0533ee@140.211.11.27:54672
I0808 07:47:21.594547 14231 sched.cpp:409] Framework registered with 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.594570 14231 sched.cpp:423] Scheduler::registered took 13424ns
I0808 07:47:21.594606 14231 hierarchical_allocator_process.hpp:326] Added framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.594614 14231 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:47:21.594619 14231 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 5820ns
I0808 07:47:21.594789 13998 master.cpp:634] Master terminating
I0808 07:47:21.597718 14234 slave.cpp:2356] master@140.211.11.27:54672 exited
W0808 07:47:21.597735 14234 slave.cpp:2359] Master disconnected! Waiting for a new master to be elected
I0808 07:47:21.597771 14234 slave.cpp:971] Will retry registration in 28.275404ms if necessary
I0808 07:47:21.601693 14256 sched.cpp:772] Aborting framework '20140808-074721-453759884-54672-13998-0000'
I0808 07:47:21.601737 14256 sched.cpp:747] Stopping framework '20140808-074721-453759884-54672-13998-0000'
I0808 07:47:21.606405 14241 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 14.193344ms
I0808 07:47:21.606482 14241 replica.cpp:676] Persisted action at 3
I0808 07:47:21.613767 13998 slave.cpp:466] Slave terminating
[ OK ] ExceptionTest.DisallowSchedulerActionsOnAbort (300 ms)
[ RUN ] ExceptionTest.DisallowSchedulerCallbacksOnAbort
Using temporary directory '/tmp/ExceptionTest_DisallowSchedulerCallbacksOnAbort_Nmnt9E'
I0808 07:47:21.663928 13998 leveldb.cpp:176] Opened db in 42.207451ms
I0808 07:47:21.697650 13998 leveldb.cpp:183] Compacted db in 33.63807ms
I0808 07:47:21.697729 13998 leveldb.cpp:198] Created db iterator in 3999ns
I0808 07:47:21.697788 13998 leveldb.cpp:204] Seeked to beginning of db in 719ns
I0808 07:47:21.697840 13998 leveldb.cpp:273] Iterated through 0 keys in the db in 357ns
I0808 07:47:21.697901 13998 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0808 07:47:21.702739 14257 master.cpp:286] Master 20140808-074721-453759884-54672-13998 (hemera.apache.org) started on 140.211.11.27:54672
I0808 07:47:21.702859 14257 master.cpp:323] Master only allowing authenticated frameworks to register
I0808 07:47:21.702924 14257 master.cpp:328] Master only allowing authenticated slaves to register
I0808 07:47:21.702980 14257 credentials.hpp:36] Loading credentials for authentication from '/tmp/ExceptionTest_DisallowSchedulerCallbacksOnAbort_Nmnt9E/credentials'
I0808 07:47:21.703161 14257 master.cpp:357] Authorization enabled
I0808 07:47:21.703661 14257 recover.cpp:425] Starting replica recovery
I0808 07:47:21.704020 14257 hierarchical_allocator_process.hpp:296] Initializing hierarchical allocator process with master : master@140.211.11.27:54672
I0808 07:47:21.704121 14257 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0808 07:47:21.704255 14257 master.cpp:1196] The newly elected leader is master@140.211.11.27:54672 with id 20140808-074721-453759884-54672-13998
I0808 07:47:21.704324 14257 master.cpp:1209] Elected as the leading master!
I0808 07:47:21.704385 14257 master.cpp:1027] Recovering from registrar
I0808 07:47:21.704496 14257 recover.cpp:451] Replica is in EMPTY status
I0808 07:47:21.704612 14257 registrar.cpp:313] Recovering registrar
I0808 07:47:21.705132 14257 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0808 07:47:21.705260 14257 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0808 07:47:21.705430 14257 recover.cpp:542] Updating replica status to STARTING
I0808 07:47:21.725018 14257 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 19.462778ms
I0808 07:47:21.725116 14257 replica.cpp:320] Persisted replica status to STARTING
I0808 07:47:21.725247 14257 recover.cpp:451] Replica is in STARTING status
I0808 07:47:21.725606 14257 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0808 07:47:21.725786 14255 recover.cpp:188] Received a recover response from a replica in STARTING status
I0808 07:47:21.737779 14234 recover.cpp:542] Updating replica status to VOTING
I0808 07:47:21.761518 14234 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 23.65172ms
I0808 07:47:21.761548 14234 replica.cpp:320] Persisted replica status to VOTING
I0808 07:47:21.761606 14234 recover.cpp:556] Successfully joined the Paxos group
I0808 07:47:21.761704 14234 recover.cpp:440] Recover process terminated
I0808 07:47:21.761852 14234 log.cpp:656] Attempting to start the writer
I0808 07:47:21.762202 14234 replica.cpp:474] Replica received implicit promise request with proposal 1
I0808 07:47:21.777310 14234 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 15.09503ms
I0808 07:47:21.777333 14234 replica.cpp:342] Persisted promised to 1
I0808 07:47:21.777533 14234 coordinator.cpp:230] Coordinator attemping to fill missing position
I0808 07:47:21.777892 14234 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0808 07:47:21.793385 14234 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 15.477426ms
I0808 07:47:21.793407 14234 replica.cpp:676] Persisted action at 0
I0808 07:47:21.810035 14249 replica.cpp:508] Replica received write request for position 0
I0808 07:47:21.810133 14249 leveldb.cpp:438] Reading position from leveldb took 16614ns
I0808 07:47:21.825459 14249 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 15.259581ms
I0808 07:47:21.825564 14249 replica.cpp:676] Persisted action at 0
I0808 07:47:21.825831 14249 replica.cpp:655] Replica received learned notice for position 0
I0808 07:47:21.845562 14249 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 19.662008ms
I0808 07:47:21.845662 14249 replica.cpp:676] Persisted action at 0
I0808 07:47:21.845717 14249 replica.cpp:661] Replica learned NOP action at position 0
I0808 07:47:21.845976 14249 log.cpp:672] Writer started with ending position 0
I0808 07:47:21.849695 14255 leveldb.cpp:438] Reading position from leveldb took 20253ns
I0808 07:47:21.851315 14264 registrar.cpp:346] Successfully fetched the registry (0B)
I0808 07:47:21.851336 14264 registrar.cpp:422] Attempting to update the 'registry'
I0808 07:47:21.852890 14264 log.cpp:680] Attempting to append 138 bytes to the log
I0808 07:47:21.852937 14264 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0808 07:47:21.853174 14264 replica.cpp:508] Replica received write request for position 1
I0808 07:47:21.865641 14264 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 12.44602ms
I0808 07:47:21.865661 14264 replica.cpp:676] Persisted action at 1
I0808 07:47:21.865852 14264 replica.cpp:655] Replica received learned notice for position 1
I0808 07:47:21.881913 14264 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 16.047097ms
I0808 07:47:21.881935 14264 replica.cpp:676] Persisted action at 1
I0808 07:47:21.881943 14264 replica.cpp:661] Replica learned APPEND action at position 1
I0808 07:47:21.882241 14229 registrar.cpp:479] Successfully updated 'registry'
I0808 07:47:21.882282 14264 log.cpp:699] Attempting to truncate the log to 1
I0808 07:47:21.882287 14229 registrar.cpp:372] Successfully recovered registrar
I0808 07:47:21.882369 14229 master.cpp:1054] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I0808 07:47:21.882467 14264 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0808 07:47:21.882658 14264 replica.cpp:508] Replica received write request for position 2
I0808 07:47:21.901247 14264 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 18.563038ms
I0808 07:47:21.901288 14264 replica.cpp:676] Persisted action at 2
I0808 07:47:21.901567 14264 replica.cpp:655] Replica received learned notice for position 2
I0808 07:47:21.917994 14264 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 16.411055ms
I0808 07:47:21.918030 14264 leveldb.cpp:401] Deleting ~1 keys from leveldb took 16294ns
I0808 07:47:21.918041 14264 replica.cpp:676] Persisted action at 2
I0808 07:47:21.918050 14264 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0808 07:47:21.930115 13998 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
I0808 07:47:21.933719 14261 slave.cpp:167] Slave started on 199)@140.211.11.27:54672
I0808 07:47:21.933747 14261 credentials.hpp:84] Loading credential for authentication from '/tmp/ExceptionTest_DisallowSchedulerCallbacksOnAbort_xaTNbJ/credential'
I0808 07:47:21.933847 14261 slave.cpp:265] Slave using credential for: test-principal
I0808 07:47:21.933944 14261 slave.cpp:278] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0808 07:47:21.934003 14261 slave.cpp:306] Slave hostname: hemera.apache.org
I0808 07:47:21.934012 14261 slave.cpp:307] Slave checkpoint: false
I0808 07:47:21.934501 14261 state.cpp:33] Recovering state from '/tmp/ExceptionTest_DisallowSchedulerCallbacksOnAbort_xaTNbJ/meta'
I0808 07:47:21.934594 14261 status_update_manager.cpp:193] Recovering status update manager
I0808 07:47:21.934646 14261 containerizer.cpp:287] Recovering containerizer
I0808 07:47:21.934882 14261 slave.cpp:3175] Finished recovery
I0808 07:47:21.935106 14261 slave.cpp:589] New master detected at master@140.211.11.27:54672
I0808 07:47:21.935127 14261 slave.cpp:663] Authenticating with master master@140.211.11.27:54672
I0808 07:47:21.935164 14261 slave.cpp:636] Detecting new master
I0808 07:47:21.935197 14261 status_update_manager.cpp:167] New master detected at master@140.211.11.27:54672
I0808 07:47:21.935226 14261 authenticatee.hpp:128] Creating new client SASL connection
I0808 07:47:21.935359 14261 master.cpp:3615] Authenticating slave(199)@140.211.11.27:54672
I0808 07:47:21.935434 13998 sched.cpp:139] Version: 0.20.0
I0808 07:47:21.935441 14261 authenticator.hpp:156] Creating new server SASL connection
I0808 07:47:21.935575 14261 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0808 07:47:21.935591 14261 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0808 07:47:21.935639 14261 authenticator.hpp:262] Received SASL authentication start
I0808 07:47:21.935678 14261 authenticator.hpp:384] Authentication requires more steps
I0808 07:47:21.935714 14261 sched.cpp:235] New master detected at master@140.211.11.27:54672
I0808 07:47:21.935727 14261 sched.cpp:285] Authenticating with master master@140.211.11.27:54672
I0808 07:47:21.935782 14268 authenticatee.hpp:128] Creating new client SASL connection
I0808 07:47:21.935794 14234 authenticatee.hpp:265] Received SASL authentication step
I0808 07:47:21.935855 14234 authenticator.hpp:290] Received SASL authentication step
I0808 07:47:21.935878 14234 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0808 07:47:21.935885 14234 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0808 07:47:21.935909 14234 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0808 07:47:21.935915 14268 master.cpp:3615] Authenticating scheduler-d29e58cd-988d-4b39-a916-e2ebc68bdb56@140.211.11.27:54672
I0808 07:47:21.936007 14268 authenticator.hpp:156] Creating new server SASL connection
I0808 07:47:21.936089 14268 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0808 07:47:21.936106 14268 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0808 07:47:21.936131 14268 authenticator.hpp:262] Received SASL authentication start
I0808 07:47:21.936159 14268 authenticator.hpp:384] Authentication requires more steps
I0808 07:47:21.936184 14268 authenticatee.hpp:265] Received SASL authentication step
I0808 07:47:21.936218 14268 authenticator.hpp:290] Received SASL authentication step
I0808 07:47:21.936233 14268 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0808 07:47:21.936241 14268 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0808 07:47:21.936252 14268 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0808 07:47:21.936264 14268 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0808 07:47:21.936271 14268 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0808 07:47:21.936278 14268 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0808 07:47:21.936290 14268 authenticator.hpp:376] Authentication success
I0808 07:47:21.936316 14268 authenticatee.hpp:305] Authentication success
I0808 07:47:21.936339 14268 master.cpp:3655] Successfully authenticated principal 'test-principal' at scheduler-d29e58cd-988d-4b39-a916-e2ebc68bdb56@140.211.11.27:54672
I0808 07:47:21.936408 14268 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:54672
I0808 07:47:21.936419 14268 sched.cpp:478] Sending registration request to master@140.211.11.27:54672
I0808 07:47:21.936461 14268 master.cpp:1315] Received registration request from scheduler-d29e58cd-988d-4b39-a916-e2ebc68bdb56@140.211.11.27:54672
I0808 07:47:21.936480 14268 master.cpp:1275] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0808 07:47:21.936579 14268 master.cpp:1374] Registering framework 20140808-074721-453759884-54672-13998-0000 at scheduler-d29e58cd-988d-4b39-a916-e2ebc68bdb56@140.211.11.27:54672
I0808 07:47:21.936666 14268 sched.cpp:409] Framework registered with 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.936687 14268 sched.cpp:423] Scheduler::registered took 9320ns
I0808 07:47:21.936720 14268 hierarchical_allocator_process.hpp:326] Added framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.936729 14268 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:47:21.936735 14268 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 7158ns
I0808 07:47:21.935920 14234 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0808 07:47:21.936760 14234 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0808 07:47:21.936768 14234 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0808 07:47:21.936781 14234 authenticator.hpp:376] Authentication success
I0808 07:47:21.936813 14234 authenticatee.hpp:305] Authentication success
I0808 07:47:21.936835 14234 master.cpp:3655] Successfully authenticated principal 'test-principal' at slave(199)@140.211.11.27:54672
I0808 07:47:21.936890 14234 slave.cpp:720] Successfully authenticated with master master@140.211.11.27:54672
I0808 07:47:21.936923 14234 slave.cpp:971] Will retry registration in 9.333331ms if necessary
I0808 07:47:21.936983 14234 master.cpp:2837] Registering slave at slave(199)@140.211.11.27:54672 (hemera.apache.org) with id 20140808-074721-453759884-54672-13998-0
I0808 07:47:21.937085 14234 registrar.cpp:422] Attempting to update the 'registry'
I0808 07:47:21.938721 14234 log.cpp:680] Attempting to append 332 bytes to the log
I0808 07:47:21.938771 14234 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0808 07:47:21.938998 14234 replica.cpp:508] Replica received write request for position 3
I0808 07:47:21.950434 14231 slave.cpp:971] Will retry registration in 32.671407ms if necessary
I0808 07:47:21.950498 14231 master.cpp:2825] Ignoring register slave message from slave(199)@140.211.11.27:54672 (hemera.apache.org) as admission is already in progress
I0808 07:47:21.957659 14234 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 18.643135ms
I0808 07:47:21.957684 14234 replica.cpp:676] Persisted action at 3
I0808 07:47:21.957897 14234 replica.cpp:655] Replica received learned notice for position 3
I0808 07:47:21.974536 14234 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 16.62411ms
I0808 07:47:21.974562 14234 replica.cpp:676] Persisted action at 3
I0808 07:47:21.974570 14234 replica.cpp:661] Replica learned APPEND action at position 3
I0808 07:47:21.974895 14234 registrar.cpp:479] Successfully updated 'registry'
I0808 07:47:21.974974 14234 log.cpp:699] Attempting to truncate the log to 3
I0808 07:47:21.975029 14234 master.cpp:2877] Registered slave 20140808-074721-453759884-54672-13998-0 at slave(199)@140.211.11.27:54672 (hemera.apache.org)
I0808 07:47:21.975042 14234 master.cpp:4088] Adding slave 20140808-074721-453759884-54672-13998-0 at slave(199)@140.211.11.27:54672 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0808 07:47:21.975146 14234 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0808 07:47:21.975210 14234 slave.cpp:754] Registered with master master@140.211.11.27:54672; given slave ID 20140808-074721-453759884-54672-13998-0
I0808 07:47:21.975286 14234 hierarchical_allocator_process.hpp:439] Added slave 20140808-074721-453759884-54672-13998-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0808 07:47:21.975340 14234 hierarchical_allocator_process.hpp:714] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-074721-453759884-54672-13998-0 to framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.975445 14234 hierarchical_allocator_process.hpp:670] Performed allocation for slave 20140808-074721-453759884-54672-13998-0 in 127632ns
I0808 07:47:21.975494 14234 slave.cpp:2324] Received ping from slave-observer(168)@140.211.11.27:54672
I0808 07:47:21.975556 14234 master.hpp:847] Adding offer 20140808-074721-453759884-54672-13998-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-074721-453759884-54672-13998-0 (hemera.apache.org)
I0808 07:47:21.975608 14234 master.cpp:3562] Sending 1 offers to framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.975738 14234 sched.cpp:546] Scheduler::resourceOffers took 19315ns
I0808 07:47:21.975919 14234 replica.cpp:508] Replica received write request for position 4
I0808 07:47:21.981397 14231 sched.cpp:772] Aborting framework '20140808-074721-453759884-54672-13998-0000'
I0808 07:47:21.981463 14231 sched.cpp:552] Ignoring rescind offer message because the driver is aborted!
I0808 07:47:21.981518 14231 master.cpp:1655] Deactivating framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.981595 14231 master.hpp:857] Removing offer 20140808-074721-453759884-54672-13998-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-074721-453759884-54672-13998-0 (hemera.apache.org)
I0808 07:47:21.981744 14259 hierarchical_allocator_process.hpp:402] Deactivated framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.981827 14259 hierarchical_allocator_process.hpp:560] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140808-074721-453759884-54672-13998-0 from framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.981853 14259 hierarchical_allocator_process.hpp:591] Framework 20140808-074721-453759884-54672-13998-0000 filtered slave 20140808-074721-453759884-54672-13998-0 for 5secs
I0808 07:47:21.985782 14271 sched.cpp:552] Ignoring rescind offer message because the driver is aborted!
I0808 07:47:21.985847 14259 sched.cpp:747] Stopping framework '20140808-074721-453759884-54672-13998-0000'
I0808 07:47:21.985931 14259 master.cpp:1608] Asked to unregister framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.985941 14259 master.cpp:3938] Removing framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.986062 14259 hierarchical_allocator_process.hpp:357] Removed framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.986222 14232 slave.cpp:1406] Asked to shut down framework 20140808-074721-453759884-54672-13998-0000 by master@140.211.11.27:54672
W0808 07:47:21.986238 14232 slave.cpp:1421] Cannot shut down unknown framework 20140808-074721-453759884-54672-13998-0000
I0808 07:47:21.986239 13998 master.cpp:634] Master terminating
I0808 07:47:21.989689 14242 slave.cpp:2356] master@140.211.11.27:54672 exited
W0808 07:47:21.989707 14242 slave.cpp:2359] Master disconnected! Waiting for a new master to be elected
I0808 07:47:21.993734 14234 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 17.762755ms
I0808 07:47:21.993777 14234 replica.cpp:676] Persisted action at 4
I0808 07:47:22.001166 13998 slave.cpp:466] Slave terminating
[ OK ] ExceptionTest.DisallowSchedulerCallbacksOnAbort (388 ms)
[----------] 3 tests from ExceptionTest (988 ms total)
[----------] 2 tests from FetcherTest
[ RUN ] FetcherTest.FileURI
Using temporary directory '/tmp/FetcherTest_FileURI_TzL7tN'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0808 07:47:22.135041 31209 fetcher.cpp:76] Fetching URI 'file:///tmp/FetcherTest_FileURI_TzL7tN/from/test'
I0808 07:47:22.135159 31209 fetcher.cpp:179] Copying resource from '/tmp/FetcherTest_FileURI_TzL7tN/from/test' to '/tmp/FetcherTest_FileURI_TzL7tN'
I0808 07:47:22.161674 31209 fetcher.cpp:255] Skipped extracting path '/tmp/FetcherTest_FileURI_TzL7tN/test'
[ OK ] FetcherTest.FileURI (928 ms)
[ RUN ] FetcherTest.FileLocalhostURI
Using temporary directory '/tmp/FetcherTest_FileLocalhostURI_XfECKU'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0808 07:47:23.071722 31256 fetcher.cpp:76] Fetching URI 'file://localhost/tmp/FetcherTest_FileLocalhostURI_XfECKU/from/test'
I0808 07:47:23.071934 31256 fetcher.cpp:179] Copying resource from '/tmp/FetcherTest_FileLocalhostURI_XfECKU/from/test' to '/tmp/FetcherTest_FileLocalhostURI_XfECKU'
I0808 07:47:23.086611 31256 fetcher.cpp:255] Skipped extracting path '/tmp/FetcherTest_FileLocalhostURI_XfECKU/test'
[ OK ] FetcherTest.FileLocalhostURI (1001 ms)
[----------] 2 tests from FetcherTest (1929 ms total)
[----------] Global test environment tear-down
[==========] 358 tests from 57 test cases ran. (328571 ms total)
[ PASSED ] 357 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] AuthenticationTest.LeaderElection
1 FAILED TEST
YOU HAVE 4 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make[1]: *** [check] Error 2
make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make: *** [check-recursive] Error 1
Build step 'Execute shell' marked build as failure
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2303
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2303/changes>
Changes:
[yan] Added 'timed_tests.sh' script to help investigate the cause of hanging tests.
[niklas] Added libprocess and stout to doxyfile.
[yujie.jay] Modified the default for ephemeral ports per container.
------------------------------------------
[...truncated 57659 lines...]
I0808 02:28:50.795085 23782 master.cpp:328] Master only allowing authenticated slaves to register
I0808 02:28:50.795096 23782 credentials.hpp:36] Loading credentials for authentication from '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_6dNMfo/credentials'
I0808 02:28:50.795215 23782 master.cpp:357] Authorization enabled
I0808 02:28:50.795604 23782 recover.cpp:425] Starting replica recovery
I0808 02:28:50.795886 23782 hierarchical_allocator_process.hpp:296] Initializing hierarchical allocator process with master : master@67.195.81.187:51892
I0808 02:28:50.795922 23782 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0808 02:28:50.795995 23782 master.cpp:1196] The newly elected leader is master@67.195.81.187:51892 with id 20140808-022850-3142697795-51892-23759
I0808 02:28:50.796010 23782 master.cpp:1209] Elected as the leading master!
I0808 02:28:50.796020 23782 master.cpp:1027] Recovering from registrar
I0808 02:28:50.796082 23782 recover.cpp:451] Replica is in EMPTY status
I0808 02:28:50.796154 23782 registrar.cpp:313] Recovering registrar
I0808 02:28:50.796795 23782 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0808 02:28:50.796864 23782 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0808 02:28:50.796985 23782 recover.cpp:542] Updating replica status to STARTING
I0808 02:28:50.797433 23782 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 383430ns
I0808 02:28:50.797453 23782 replica.cpp:320] Persisted replica status to STARTING
I0808 02:28:50.797525 23782 recover.cpp:451] Replica is in STARTING status
I0808 02:28:50.797889 23782 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0808 02:28:50.797951 23782 recover.cpp:188] Received a recover response from a replica in STARTING status
I0808 02:28:50.798075 23782 recover.cpp:542] Updating replica status to VOTING
I0808 02:28:50.798262 23782 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 129390ns
I0808 02:28:50.798282 23782 replica.cpp:320] Persisted replica status to VOTING
I0808 02:28:50.798354 23785 recover.cpp:556] Successfully joined the Paxos group
I0808 02:28:50.798421 23785 recover.cpp:440] Recover process terminated
I0808 02:28:50.798554 23782 log.cpp:656] Attempting to start the writer
I0808 02:28:50.798969 23785 replica.cpp:474] Replica received implicit promise request with proposal 1
I0808 02:28:50.799079 23785 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 90246ns
I0808 02:28:50.799098 23785 replica.cpp:342] Persisted promised to 1
I0808 02:28:50.799311 23785 coordinator.cpp:230] Coordinator attemping to fill missing position
I0808 02:28:50.799738 23785 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0808 02:28:50.799849 23785 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 91823ns
I0808 02:28:50.799867 23785 replica.cpp:676] Persisted action at 0
I0808 02:28:50.800339 23779 replica.cpp:508] Replica received write request for position 0
I0808 02:28:50.800366 23779 leveldb.cpp:438] Reading position from leveldb took 11253ns
I0808 02:28:50.800475 23779 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 92004ns
I0808 02:28:50.800598 23779 replica.cpp:676] Persisted action at 0
I0808 02:28:50.800827 23779 replica.cpp:655] Replica received learned notice for position 0
I0808 02:28:50.801194 23779 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 272166ns
I0808 02:28:50.801214 23779 replica.cpp:676] Persisted action at 0
I0808 02:28:50.801224 23779 replica.cpp:661] Replica learned NOP action at position 0
I0808 02:28:50.801419 23782 log.cpp:672] Writer started with ending position 0
I0808 02:28:50.801725 23782 leveldb.cpp:438] Reading position from leveldb took 10242ns
I0808 02:28:50.803284 23782 registrar.cpp:346] Successfully fetched the registry (0B)
I0808 02:28:50.803311 23782 registrar.cpp:422] Attempting to update the 'registry'
I0808 02:28:50.804925 23782 log.cpp:680] Attempting to append 139 bytes to the log
I0808 02:28:50.804978 23782 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0808 02:28:50.805178 23782 replica.cpp:508] Replica received write request for position 1
I0808 02:28:50.805464 23782 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 266144ns
I0808 02:28:50.805480 23782 replica.cpp:676] Persisted action at 1
I0808 02:28:50.805667 23782 replica.cpp:655] Replica received learned notice for position 1
I0808 02:28:50.805810 23782 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 126597ns
I0808 02:28:50.805826 23782 replica.cpp:676] Persisted action at 1
I0808 02:28:50.805836 23782 replica.cpp:661] Replica learned APPEND action at position 1
I0808 02:28:50.806093 23782 registrar.cpp:479] Successfully updated 'registry'
I0808 02:28:50.806133 23782 registrar.cpp:372] Successfully recovered registrar
I0808 02:28:50.806171 23782 log.cpp:699] Attempting to truncate the log to 1
I0808 02:28:50.806236 23782 master.cpp:1054] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register
I0808 02:28:50.806277 23782 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0808 02:28:50.806500 23782 replica.cpp:508] Replica received write request for position 2
I0808 02:28:50.806614 23782 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 97064ns
I0808 02:28:50.806630 23782 replica.cpp:676] Persisted action at 2
I0808 02:28:50.806813 23782 replica.cpp:655] Replica received learned notice for position 2
I0808 02:28:50.806941 23782 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 110161ns
I0808 02:28:50.806977 23782 leveldb.cpp:401] Deleting ~1 keys from leveldb took 16586ns
I0808 02:28:50.806993 23782 replica.cpp:676] Persisted action at 2
I0808 02:28:50.807005 23782 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0808 02:28:50.819766 23794 slave.cpp:167] Slave started on 200)@67.195.81.187:51892
I0808 02:28:50.819788 23794 credentials.hpp:84] Loading credential for authentication from '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/credential'
I0808 02:28:50.819870 23794 slave.cpp:265] Slave using credential for: test-principal
I0808 02:28:50.819983 23794 slave.cpp:278] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0808 02:28:50.820055 23794 slave.cpp:306] Slave hostname: pomona.apache.org
I0808 02:28:50.820070 23794 slave.cpp:307] Slave checkpoint: true
I0808 02:28:50.820561 23794 state.cpp:33] Recovering state from '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/meta'
I0808 02:28:50.820672 23794 status_update_manager.cpp:193] Recovering status update manager
I0808 02:28:50.820780 23794 slave.cpp:3175] Finished recovery
I0808 02:28:50.821033 23794 slave.cpp:589] New master detected at master@67.195.81.187:51892
I0808 02:28:50.821063 23794 slave.cpp:663] Authenticating with master master@67.195.81.187:51892
I0808 02:28:50.821113 23794 slave.cpp:636] Detecting new master
I0808 02:28:50.821161 23794 status_update_manager.cpp:167] New master detected at master@67.195.81.187:51892
I0808 02:28:50.821204 23794 authenticatee.hpp:128] Creating new client SASL connection
I0808 02:28:50.821305 23794 master.cpp:3615] Authenticating slave(200)@67.195.81.187:51892
I0808 02:28:50.821400 23794 authenticator.hpp:156] Creating new server SASL connection
I0808 02:28:50.821470 23794 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0808 02:28:50.821492 23794 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0808 02:28:50.821529 23794 authenticator.hpp:262] Received SASL authentication start
I0808 02:28:50.821571 23794 authenticator.hpp:384] Authentication requires more steps
I0808 02:28:50.821609 23794 authenticatee.hpp:265] Received SASL authentication step
I0808 02:28:50.821660 23794 authenticator.hpp:290] Received SASL authentication step
I0808 02:28:50.821683 23794 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0808 02:28:50.821697 23794 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0808 02:28:50.821713 23794 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0808 02:28:50.821729 23794 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0808 02:28:50.821741 23794 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0808 02:28:50.821750 23794 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0808 02:28:50.821769 23794 authenticator.hpp:376] Authentication success
I0808 02:28:50.821806 23794 authenticatee.hpp:305] Authentication success
I0808 02:28:50.821838 23794 master.cpp:3655] Successfully authenticated principal 'test-principal' at slave(200)@67.195.81.187:51892
I0808 02:28:50.821921 23794 slave.cpp:720] Successfully authenticated with master master@67.195.81.187:51892
I0808 02:28:50.821964 23794 slave.cpp:971] Will retry registration in 11.416226ms if necessary
I0808 02:28:50.822044 23794 master.cpp:2837] Registering slave at slave(200)@67.195.81.187:51892 (pomona.apache.org) with id 20140808-022850-3142697795-51892-23759-0
I0808 02:28:50.822165 23794 registrar.cpp:422] Attempting to update the 'registry'
I0808 02:28:50.823211 23759 sched.cpp:139] Version: 0.20.0
I0808 02:28:50.823902 23794 log.cpp:680] Attempting to append 334 bytes to the log
I0808 02:28:50.823971 23794 sched.cpp:235] New master detected at master@67.195.81.187:51892
I0808 02:28:50.823992 23794 sched.cpp:285] Authenticating with master master@67.195.81.187:51892
I0808 02:28:50.824071 23794 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0808 02:28:50.824156 23794 authenticatee.hpp:128] Creating new client SASL connection
I0808 02:28:50.824282 23794 master.cpp:3615] Authenticating scheduler-e9cf303c-2596-4d6d-a8fd-cb61e3d6b95a@67.195.81.187:51892
I0808 02:28:50.824396 23794 authenticator.hpp:156] Creating new server SASL connection
I0808 02:28:50.824645 23787 replica.cpp:508] Replica received write request for position 3
I0808 02:28:50.824802 23787 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 134796ns
I0808 02:28:50.824822 23787 replica.cpp:676] Persisted action at 3
I0808 02:28:50.825058 23787 replica.cpp:655] Replica received learned notice for position 3
I0808 02:28:50.825287 23790 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0808 02:28:50.825315 23790 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0808 02:28:50.825392 23787 leveldb.cpp:343] Persisting action (355 bytes) to leveldb took 309722ns
I0808 02:28:50.825417 23787 replica.cpp:676] Persisted action at 3
I0808 02:28:50.825428 23787 replica.cpp:661] Replica learned APPEND action at position 3
I0808 02:28:50.825460 23786 authenticator.hpp:262] Received SASL authentication start
I0808 02:28:50.825507 23786 authenticator.hpp:384] Authentication requires more steps
I0808 02:28:50.825546 23786 authenticatee.hpp:265] Received SASL authentication step
I0808 02:28:50.825628 23787 authenticator.hpp:290] Received SASL authentication step
I0808 02:28:50.825650 23787 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0808 02:28:50.825661 23787 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0808 02:28:50.825673 23787 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0808 02:28:50.825686 23787 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0808 02:28:50.825695 23787 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0808 02:28:50.825706 23787 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0808 02:28:50.825722 23787 authenticator.hpp:376] Authentication success
I0808 02:28:50.825788 23787 registrar.cpp:479] Successfully updated 'registry'
I0808 02:28:50.825896 23787 authenticatee.hpp:305] Authentication success
I0808 02:28:50.825923 23787 master.cpp:3655] Successfully authenticated principal 'test-principal' at scheduler-e9cf303c-2596-4d6d-a8fd-cb61e3d6b95a@67.195.81.187:51892
I0808 02:28:50.826014 23787 master.cpp:2877] Registered slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org)
I0808 02:28:50.826030 23787 master.cpp:4088] Adding slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0808 02:28:50.826166 23787 sched.cpp:359] Successfully authenticated with master master@67.195.81.187:51892
I0808 02:28:50.826182 23787 sched.cpp:478] Sending registration request to master@67.195.81.187:51892
I0808 02:28:50.826221 23787 slave.cpp:754] Registered with master master@67.195.81.187:51892; given slave ID 20140808-022850-3142697795-51892-23759-0
I0808 02:28:50.826366 23787 slave.cpp:767] Checkpointing SlaveInfo to '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/meta/slaves/20140808-022850-3142697795-51892-23759-0/slave.info'
I0808 02:28:50.826526 23787 hierarchical_allocator_process.hpp:439] Added slave 20140808-022850-3142697795-51892-23759-0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0808 02:28:50.826568 23787 hierarchical_allocator_process.hpp:670] Performed allocation for slave 20140808-022850-3142697795-51892-23759-0 in 5521ns
I0808 02:28:50.826603 23787 master.cpp:1315] Received registration request from scheduler-e9cf303c-2596-4d6d-a8fd-cb61e3d6b95a@67.195.81.187:51892
I0808 02:28:50.826623 23787 master.cpp:1275] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0808 02:28:50.826675 23787 slave.cpp:2324] Received ping from slave-observer(180)@67.195.81.187:51892
I0808 02:28:50.826760 23787 master.cpp:1374] Registering framework 20140808-022850-3142697795-51892-23759-0000 at scheduler-e9cf303c-2596-4d6d-a8fd-cb61e3d6b95a@67.195.81.187:51892
I0808 02:28:50.826841 23787 sched.cpp:409] Framework registered with 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.826864 23787 sched.cpp:423] Scheduler::registered took 10125ns
I0808 02:28:50.826895 23787 hierarchical_allocator_process.hpp:326] Added framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.826936 23787 hierarchical_allocator_process.hpp:714] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-022850-3142697795-51892-23759-0 to framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.827045 23787 hierarchical_allocator_process.hpp:650] Performed allocation for 1 slaves in 135848ns
I0808 02:28:50.827133 23787 master.hpp:847] Adding offer 20140808-022850-3142697795-51892-23759-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-022850-3142697795-51892-23759-0 (pomona.apache.org)
I0808 02:28:50.827193 23787 master.cpp:3562] Sending 1 offers to framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.827291 23787 sched.cpp:546] Scheduler::resourceOffers took 20738ns
I0808 02:28:50.827513 23786 log.cpp:699] Attempting to truncate the log to 3
I0808 02:28:50.827628 23786 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0808 02:28:50.827795 23786 master.hpp:857] Removing offer 20140808-022850-3142697795-51892-23759-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-022850-3142697795-51892-23759-0 (pomona.apache.org)
I0808 02:28:50.827857 23786 master.cpp:2199] Processing reply for offers: [ 20140808-022850-3142697795-51892-23759-0 ] on slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org) for framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.827889 23786 master.cpp:2285] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
I0808 02:28:50.828243 23786 master.hpp:819] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-022850-3142697795-51892-23759-0 (pomona.apache.org)
I0808 02:28:50.828287 23786 master.cpp:2351] Launching task 1 of framework 20140808-022850-3142697795-51892-23759-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org)
I0808 02:28:50.828482 23781 slave.cpp:1002] Got assigned task 1 for framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.828562 23781 slave.cpp:3513] Checkpointing FrameworkInfo to '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/meta/slaves/20140808-022850-3142697795-51892-23759-0/frameworks/20140808-022850-3142697795-51892-23759-0000/framework.info'
I0808 02:28:50.828699 23781 slave.cpp:3520] Checkpointing framework pid 'scheduler-e9cf303c-2596-4d6d-a8fd-cb61e3d6b95a@67.195.81.187:51892' to '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/meta/slaves/20140808-022850-3142697795-51892-23759-0/frameworks/20140808-022850-3142697795-51892-23759-0000/framework.pid'
I0808 02:28:50.828918 23781 slave.cpp:1112] Launching task 1 for framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.830569 23781 slave.cpp:3829] Checkpointing ExecutorInfo to '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/meta/slaves/20140808-022850-3142697795-51892-23759-0/frameworks/20140808-022850-3142697795-51892-23759-0000/executors/default/executor.info'
I0808 02:28:50.831068 23784 replica.cpp:508] Replica received write request for position 4
I0808 02:28:50.836434 23784 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.347891ms
I0808 02:28:50.836460 23784 replica.cpp:676] Persisted action at 4
I0808 02:28:50.836662 23784 replica.cpp:655] Replica received learned notice for position 4
I0808 02:28:50.836987 23784 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 306885ns
I0808 02:28:50.837021 23784 leveldb.cpp:401] Deleting ~2 keys from leveldb took 17073ns
I0808 02:28:50.837034 23784 replica.cpp:676] Persisted action at 4
I0808 02:28:50.837044 23784 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0808 02:28:50.837730 23781 exec.cpp:131] Version: 0.20.0
I0808 02:28:50.837822 23785 exec.cpp:181] Executor started at: executor(62)@67.195.81.187:51892 with pid 23759
I0808 02:28:50.837859 23781 slave.cpp:3944] Checkpointing TaskInfo to '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/meta/slaves/20140808-022850-3142697795-51892-23759-0/frameworks/20140808-022850-3142697795-51892-23759-0000/executors/default/runs/ab6b7f4c-8870-43d1-bc84-980c19c51292/tasks/1/task.info'
I0808 02:28:50.838028 23781 slave.cpp:1222] Queuing task '1' for executor default of framework '20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.838075 23781 slave.cpp:543] Successfully attached file '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/slaves/20140808-022850-3142697795-51892-23759-0/frameworks/20140808-022850-3142697795-51892-23759-0000/executors/default/runs/ab6b7f4c-8870-43d1-bc84-980c19c51292'
I0808 02:28:50.838114 23781 slave.cpp:2515] Monitoring executor 'default' of framework '20140808-022850-3142697795-51892-23759-0000' in container 'ab6b7f4c-8870-43d1-bc84-980c19c51292'
I0808 02:28:50.838280 23781 slave.cpp:1733] Got registration for executor 'default' of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.838313 23781 slave.cpp:1818] Checkpointing executor pid 'executor(62)@67.195.81.187:51892' to '/tmp/StatusUpdateManagerTest_IgnoreDuplicateStatusUpdateAck_gG3bfJ/meta/slaves/20140808-022850-3142697795-51892-23759-0/frameworks/20140808-022850-3142697795-51892-23759-0000/executors/default/runs/ab6b7f4c-8870-43d1-bc84-980c19c51292/pids/libprocess.pid'
I0808 02:28:50.838537 23781 slave.cpp:1852] Flushing queued task 1 for executor 'default' of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.838605 23792 exec.cpp:205] Executor registered on slave 20140808-022850-3142697795-51892-23759-0
I0808 02:28:50.839979 23792 exec.cpp:217] Executor::registered took 11729ns
I0808 02:28:50.840047 23792 exec.cpp:292] Executor asked to run task '1'
I0808 02:28:50.840080 23792 exec.cpp:301] Executor::launchTask took 20683ns
I0808 02:28:50.841507 23792 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.841598 23792 slave.cpp:2087] Handling status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 from executor(62)@67.195.81.187:51892
I0808 02:28:50.841688 23792 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.841704 23792 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.841857 23792 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.842437 23792 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 to master@67.195.81.187:51892
I0808 02:28:50.842567 23792 master.cpp:3206] Forwarding status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.842608 23792 master.cpp:3172] Status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 from slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org)
I0808 02:28:50.842643 23792 slave.cpp:2245] Status update manager successfully handled status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.842656 23792 slave.cpp:2251] Sending acknowledgement for status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 to executor(62)@67.195.81.187:51892
I0808 02:28:50.842736 23792 exec.cpp:338] Executor received status update acknowledgement 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.848028 23792 hierarchical_allocator_process.hpp:650] Performed allocation for 1 slaves in 23166ns
I0808 02:28:50.848080 23792 master.cpp:120] No whitelist given. Advertising offers for all slaves
W0808 02:28:50.848127 23792 status_update_manager.cpp:477] Resending status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.848141 23792 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 to master@67.195.81.187:51892
I0808 02:28:50.848217 23792 master.cpp:3206] Forwarding status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.848254 23792 master.cpp:3172] Status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 from slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org)
I0808 02:28:50.848320 23792 sched.cpp:637] Scheduler::statusUpdate took 11222ns
I0808 02:28:50.848368 23792 master.cpp:2687] Forwarding status update acknowledgement 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 to slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org)
I0808 02:28:50.848484 23790 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.848513 23790 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.863870 23790 slave.cpp:1673] Status update manager successfully handled status update acknowledgement (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.880264 23792 exec.cpp:524] Executor sending status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.880345 23792 slave.cpp:2087] Handling status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 from executor(62)@67.195.81.187:51892
I0808 02:28:50.880369 23792 slave.cpp:3877] Terminating task 1
I0808 02:28:50.880623 23792 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.880646 23792 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.881160 23792 status_update_manager.cpp:373] Forwarding status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 to master@67.195.81.187:51892
I0808 02:28:50.881279 23792 master.cpp:3206] Forwarding status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.881319 23792 master.cpp:3172] Status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 from slave 20140808-022850-3142697795-51892-23759-0 at slave(200)@67.195.81.187:51892 (pomona.apache.org)
I0808 02:28:50.881381 23792 master.hpp:837] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140808-022850-3142697795-51892-23759-0 (pomona.apache.org)
I0808 02:28:50.881479 23792 slave.cpp:2245] Status update manager successfully handled status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.881494 23792 slave.cpp:2251] Sending acknowledgement for status update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000 to executor(62)@67.195.81.187:51892
I0808 02:28:50.881613 23792 hierarchical_allocator_process.hpp:560] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140808-022850-3142697795-51892-23759-0 from framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.881642 23792 hierarchical_allocator_process.hpp:591] Framework 20140808-022850-3142697795-51892-23759-0000 filtered slave 20140808-022850-3142697795-51892-23759-0 for 5secs
I0808 02:28:50.881683 23792 exec.cpp:338] Executor received status update acknowledgement 63b4ed7a-71c6-400f-9c91-621ec9c990c9 for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
I0808 02:28:50.892495 23781 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
W0808 02:28:50.892524 23781 status_update_manager.hpp:259] Duplicate status update acknowledgment (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for update TASK_FINISHED (UUID: 63b4ed7a-71c6-400f-9c91-621ec9c990c9) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000
E0808 02:28:50.892572 23781 slave.cpp:1666] Failed to handle status update acknowledgement (UUID: 4cdfe6a0-38c7-4ca1-8018-fce761a0a73d) for task 1 of framework 20140808-022850-3142697795-51892-23759-0000: Duplicate acknowledgement
I0808 02:28:50.901175 23787 sched.cpp:747] Stopping framework '20140808-022850-3142697795-51892-23759-0000'
I0808 02:28:50.901190 23793 master.cpp:634] Master terminating
I0808 02:28:50.920505 23784 slave.cpp:2356] master@67.195.81.187:51892 exited
W0808 02:28:50.920524 23784 slave.cpp:2359] Master disconnected! Waiting for a new master to be elected
I0808 02:28:50.921746 23759 slave.cpp:466] Slave terminating
[ OK ] StatusUpdateManagerTest.IgnoreDuplicateStatusUpdateAck (132 ms)
[----------] 7 tests from StatusUpdateManagerTest (947 ms total)
[----------] Global test environment tear-down
[==========] 359 tests from 57 test cases ran. (208502 ms total)
[ PASSED ] 358 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] HealthCheckTest.ConsecutiveFailures
1 FAILED TEST
YOU HAVE 3 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'>
make: *** [check-recursive] Error 1
Build step 'Execute shell' marked build as failure
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui
#2302
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2302/changes>
Changes:
[yan] Reverted a refactor that broke the build.
------------------------------------------
[...truncated 57701 lines...]
I0807 19:42:11.387619 1148 registrar.cpp:346] Successfully fetched the registry (0B)
I0807 19:42:11.387641 1148 registrar.cpp:422] Attempting to update the 'registry'
I0807 19:42:11.389155 1148 log.cpp:680] Attempting to append 138 bytes to the log
I0807 19:42:11.389207 1148 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0807 19:42:11.389456 1148 replica.cpp:508] Replica received write request for position 1
I0807 19:42:11.405675 1148 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 16.183123ms
I0807 19:42:11.405767 1148 replica.cpp:676] Persisted action at 1
I0807 19:42:11.406052 1148 replica.cpp:655] Replica received learned notice for position 1
I0807 19:42:11.421676 1148 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 15.549434ms
I0807 19:42:11.421772 1148 replica.cpp:676] Persisted action at 1
I0807 19:42:11.421831 1148 replica.cpp:661] Replica learned APPEND action at position 1
I0807 19:42:11.422168 1148 registrar.cpp:479] Successfully updated 'registry'
I0807 19:42:11.422266 1148 registrar.cpp:372] Successfully recovered registrar
I0807 19:42:11.422363 1148 log.cpp:699] Attempting to truncate the log to 1
I0807 19:42:11.422490 1148 master.cpp:1054] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I0807 19:42:11.422588 1148 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0807 19:42:11.422907 1148 replica.cpp:508] Replica received write request for position 2
I0807 19:42:11.441656 1148 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 18.675953ms
I0807 19:42:11.441747 1148 replica.cpp:676] Persisted action at 2
I0807 19:42:11.441998 1148 replica.cpp:655] Replica received learned notice for position 2
I0807 19:42:11.457660 1148 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.588379ms
I0807 19:42:11.457777 1148 leveldb.cpp:401] Deleting ~1 keys from leveldb took 28347ns
I0807 19:42:11.457841 1148 replica.cpp:676] Persisted action at 2
I0807 19:42:11.457897 1148 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0807 19:42:11.463836 32388 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
I0807 19:42:11.466023 1137 slave.cpp:167] Slave started on 199)@140.211.11.27:45707
I0807 19:42:11.466044 1137 credentials.hpp:84] Loading credential for authentication from '/tmp/CredentialsTest_authenticatedSlave_7EiNbg/credential'
I0807 19:42:11.466138 1137 slave.cpp:265] Slave using credential for: test-principal
I0807 19:42:11.466262 1137 slave.cpp:278] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0807 19:42:11.466313 1137 slave.cpp:306] Slave hostname: hemera.apache.org
I0807 19:42:11.466323 1137 slave.cpp:307] Slave checkpoint: false
I0807 19:42:11.466924 1137 state.cpp:33] Recovering state from '/tmp/CredentialsTest_authenticatedSlave_7EiNbg/meta'
I0807 19:42:11.467017 1137 status_update_manager.cpp:193] Recovering status update manager
I0807 19:42:11.467075 1137 containerizer.cpp:287] Recovering containerizer
I0807 19:42:11.467334 1137 slave.cpp:3175] Finished recovery
I0807 19:42:11.467541 1137 slave.cpp:589] New master detected at master@140.211.11.27:45707
I0807 19:42:11.467562 1137 slave.cpp:663] Authenticating with master master@140.211.11.27:45707
I0807 19:42:11.467598 1137 slave.cpp:636] Detecting new master
I0807 19:42:11.467632 1137 status_update_manager.cpp:167] New master detected at master@140.211.11.27:45707
I0807 19:42:11.467666 1137 authenticatee.hpp:128] Creating new client SASL connection
I0807 19:42:11.467782 1137 master.cpp:3615] Authenticating slave(199)@140.211.11.27:45707
I0807 19:42:11.467936 1119 authenticator.hpp:156] Creating new server SASL connection
I0807 19:42:11.468049 1119 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0807 19:42:11.468066 1119 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0807 19:42:11.468094 1119 authenticator.hpp:262] Received SASL authentication start
I0807 19:42:11.468133 1119 authenticator.hpp:384] Authentication requires more steps
I0807 19:42:11.468368 1160 authenticatee.hpp:265] Received SASL authentication step
I0807 19:42:11.468420 1160 authenticator.hpp:290] Received SASL authentication step
I0807 19:42:11.468435 1160 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0807 19:42:11.468441 1160 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0807 19:42:11.468451 1160 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0807 19:42:11.468459 1160 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0807 19:42:11.468466 1160 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0807 19:42:11.468469 1160 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0807 19:42:11.468480 1160 authenticator.hpp:376] Authentication success
I0807 19:42:11.468505 1160 authenticatee.hpp:305] Authentication success
I0807 19:42:11.468525 1160 master.cpp:3655] Successfully authenticated principal 'test-principal' at slave(199)@140.211.11.27:45707
I0807 19:42:11.468590 1160 slave.cpp:720] Successfully authenticated with master master@140.211.11.27:45707
I0807 19:42:11.468621 1160 slave.cpp:971] Will retry registration in 7.034119ms if necessary
I0807 19:42:11.468679 1160 master.cpp:2837] Registering slave at slave(199)@140.211.11.27:45707 (hemera.apache.org) with id 20140807-194211-453759884-45707-32388-0
I0807 19:42:11.468781 1160 registrar.cpp:422] Attempting to update the 'registry'
I0807 19:42:11.470397 1160 log.cpp:680] Attempting to append 332 bytes to the log
I0807 19:42:11.470448 1160 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0807 19:42:11.470662 1160 replica.cpp:508] Replica received write request for position 3
I0807 19:42:11.489660 1160 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 18.979569ms
I0807 19:42:11.489687 1160 replica.cpp:676] Persisted action at 3
I0807 19:42:11.489887 1160 replica.cpp:655] Replica received learned notice for position 3
I0807 19:42:11.497858 1114 slave.cpp:971] Will retry registration in 36.729287ms if necessary
I0807 19:42:11.497918 1114 master.cpp:2825] Ignoring register slave message from slave(199)@140.211.11.27:45707 (hemera.apache.org) as admission is already in progress
I0807 19:42:11.509659 1160 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 19.754977ms
I0807 19:42:11.509685 1160 replica.cpp:676] Persisted action at 3
I0807 19:42:11.509693 1160 replica.cpp:661] Replica learned APPEND action at position 3
I0807 19:42:11.513778 1114 log.cpp:699] Attempting to truncate the log to 3
I0807 19:42:11.513828 1114 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0807 19:42:11.514034 1114 replica.cpp:508] Replica received write request for position 4
I0807 19:42:11.515076 1154 registrar.cpp:479] Successfully updated 'registry'
I0807 19:42:11.515190 1154 master.cpp:2877] Registered slave 20140807-194211-453759884-45707-32388-0 at slave(199)@140.211.11.27:45707 (hemera.apache.org)
I0807 19:42:11.515205 1154 master.cpp:4088] Adding slave 20140807-194211-453759884-45707-32388-0 at slave(199)@140.211.11.27:45707 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0807 19:42:11.515336 1130 slave.cpp:754] Registered with master master@140.211.11.27:45707; given slave ID 20140807-194211-453759884-45707-32388-0
I0807 19:42:11.515375 1130 slave.cpp:2324] Received ping from slave-observer(170)@140.211.11.27:45707
I0807 19:42:11.515390 1154 hierarchical_allocator_process.hpp:439] Added slave 20140807-194211-453759884-45707-32388-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0807 19:42:11.515429 1154 hierarchical_allocator_process.hpp:670] Performed allocation for slave 20140807-194211-453759884-45707-32388-0 in 7979ns
I0807 19:42:11.515568 1140 master.cpp:634] Master terminating
I0807 19:42:11.515650 1140 slave.cpp:2356] master@140.211.11.27:45707 exited
W0807 19:42:11.515661 1140 slave.cpp:2359] Master disconnected! Waiting for a new master to be elected
I0807 19:42:11.528040 1114 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.982848ms
I0807 19:42:11.528066 1114 replica.cpp:676] Persisted action at 4
I0807 19:42:11.541705 1110 slave.cpp:466] Slave terminating
[ OK ] CredentialsTest.authenticatedSlave (412 ms)
[ RUN ] CredentialsTest.authenticatedSlaveText
Using temporary directory '/tmp/CredentialsTest_authenticatedSlaveText_bug0ES'
I0807 19:42:11.653785 32388 leveldb.cpp:176] Opened db in 58.539043ms
I0807 19:42:11.689654 32388 leveldb.cpp:183] Compacted db in 35.835568ms
I0807 19:42:11.689684 32388 leveldb.cpp:198] Created db iterator in 4145ns
I0807 19:42:11.689692 32388 leveldb.cpp:204] Seeked to beginning of db in 751ns
I0807 19:42:11.689698 32388 leveldb.cpp:273] Iterated through 0 keys in the db in 334ns
I0807 19:42:11.689714 32388 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0807 19:42:11.690660 1154 master.cpp:286] Master 20140807-194211-453759884-45707-32388 (hemera.apache.org) started on 140.211.11.27:45707
I0807 19:42:11.690686 1154 master.cpp:323] Master only allowing authenticated frameworks to register
I0807 19:42:11.690692 1154 master.cpp:328] Master only allowing authenticated slaves to register
I0807 19:42:11.690701 1154 credentials.hpp:36] Loading credentials for authentication from '/tmp/CredentialsTest_authenticatedSlaveText_bug0ES/credentials'
I0807 19:42:11.690784 1154 master.cpp:357] Authorization enabled
I0807 19:42:11.691277 1154 recover.cpp:425] Starting replica recovery
I0807 19:42:11.691341 1114 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0807 19:42:11.691408 1114 recover.cpp:451] Replica is in EMPTY status
I0807 19:42:11.691447 1110 hierarchical_allocator_process.hpp:296] Initializing hierarchical allocator process with master : master@140.211.11.27:45707
I0807 19:42:11.691669 1155 master.cpp:1196] The newly elected leader is master@140.211.11.27:45707 with id 20140807-194211-453759884-45707-32388
I0807 19:42:11.691684 1155 master.cpp:1209] Elected as the leading master!
I0807 19:42:11.691690 1155 master.cpp:1027] Recovering from registrar
I0807 19:42:11.691742 1114 registrar.cpp:313] Recovering registrar
I0807 19:42:11.692219 1145 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0807 19:42:11.692533 1133 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0807 19:42:11.695026 1137 recover.cpp:542] Updating replica status to STARTING
I0807 19:42:11.711560 1137 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.467597ms
I0807 19:42:11.711588 1137 replica.cpp:320] Persisted replica status to STARTING
I0807 19:42:11.711673 1137 recover.cpp:451] Replica is in STARTING status
I0807 19:42:11.711980 1137 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0807 19:42:11.712038 1137 recover.cpp:188] Received a recover response from a replica in STARTING status
I0807 19:42:11.712143 1137 recover.cpp:542] Updating replica status to VOTING
I0807 19:42:11.728981 1137 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.78504ms
I0807 19:42:11.729007 1137 replica.cpp:320] Persisted replica status to VOTING
I0807 19:42:11.729054 1137 recover.cpp:556] Successfully joined the Paxos group
I0807 19:42:11.729337 1137 recover.cpp:440] Recover process terminated
I0807 19:42:11.729470 1137 log.cpp:656] Attempting to start the writer
I0807 19:42:11.733830 1114 replica.cpp:474] Replica received implicit promise request with proposal 1
I0807 19:42:11.751832 1114 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 17.979382ms
I0807 19:42:11.751854 1114 replica.cpp:342] Persisted promised to 1
I0807 19:42:11.752063 1114 coordinator.cpp:230] Coordinator attemping to fill missing position
I0807 19:42:11.752410 1114 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0807 19:42:11.769652 1114 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 17.225061ms
I0807 19:42:11.769675 1114 replica.cpp:676] Persisted action at 0
I0807 19:42:11.769973 1114 replica.cpp:508] Replica received write request for position 0
I0807 19:42:11.769996 1114 leveldb.cpp:438] Reading position from leveldb took 11988ns
I0807 19:42:11.789651 1114 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 19.641727ms
I0807 19:42:11.789674 1114 replica.cpp:676] Persisted action at 0
I0807 19:42:11.789832 1114 replica.cpp:655] Replica received learned notice for position 0
I0807 19:42:11.809653 1114 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 19.803251ms
I0807 19:42:11.809674 1114 replica.cpp:676] Persisted action at 0
I0807 19:42:11.809681 1114 replica.cpp:661] Replica learned NOP action at position 0
I0807 19:42:11.809861 1114 log.cpp:672] Writer started with ending position 0
I0807 19:42:11.810125 1114 leveldb.cpp:438] Reading position from leveldb took 8179ns
I0807 19:42:11.811671 1114 registrar.cpp:346] Successfully fetched the registry (0B)
I0807 19:42:11.811689 1114 registrar.cpp:422] Attempting to update the 'registry'
I0807 19:42:11.813236 1114 log.cpp:680] Attempting to append 138 bytes to the log
I0807 19:42:11.813279 1114 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0807 19:42:11.813474 1114 replica.cpp:508] Replica received write request for position 1
I0807 19:42:11.833653 1114 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 20.164451ms
I0807 19:42:11.833677 1114 replica.cpp:676] Persisted action at 1
I0807 19:42:11.833868 1114 replica.cpp:655] Replica received learned notice for position 1
I0807 19:42:11.853657 1114 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 19.773749ms
I0807 19:42:11.853770 1114 replica.cpp:676] Persisted action at 1
I0807 19:42:11.853827 1114 replica.cpp:661] Replica learned APPEND action at position 1
I0807 19:42:11.854149 1114 registrar.cpp:479] Successfully updated 'registry'
I0807 19:42:11.854403 1114 registrar.cpp:372] Successfully recovered registrar
I0807 19:42:11.854501 1114 log.cpp:699] Attempting to truncate the log to 1
I0807 19:42:11.854626 1114 master.cpp:1054] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I0807 19:42:11.854719 1114 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0807 19:42:11.855016 1114 replica.cpp:508] Replica received write request for position 2
I0807 19:42:11.873654 1114 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 18.570214ms
I0807 19:42:11.873729 1114 replica.cpp:676] Persisted action at 2
I0807 19:42:11.873976 1114 replica.cpp:655] Replica received learned notice for position 2
I0807 19:42:11.892839 1114 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 18.796608ms
I0807 19:42:11.892931 1114 leveldb.cpp:401] Deleting ~1 keys from leveldb took 17767ns
I0807 19:42:11.892994 1114 replica.cpp:676] Persisted action at 2
I0807 19:42:11.893049 1114 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0807 19:42:11.902459 32388 containerizer.cpp:124] Using isolation: posix/cpu,posix/mem
I0807 19:42:11.905789 1129 slave.cpp:167] Slave started on 200)@140.211.11.27:45707
I0807 19:42:11.905818 1129 credentials.hpp:84] Loading credential for authentication from '/tmp/CredentialsTest_authenticatedSlaveText_bug0ES/credentials'
I0807 19:42:11.905889 1129 slave.cpp:265] Slave using credential for: test-principal
I0807 19:42:11.905989 1129 slave.cpp:278] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0807 19:42:11.906044 1129 slave.cpp:306] Slave hostname: hemera.apache.org
I0807 19:42:11.906051 1129 slave.cpp:307] Slave checkpoint: false
I0807 19:42:11.906630 1129 state.cpp:33] Recovering state from '/tmp/CredentialsTest_authenticatedSlaveText_DH0d7v/meta'
I0807 19:42:11.906731 1129 status_update_manager.cpp:193] Recovering status update manager
I0807 19:42:11.906787 1129 containerizer.cpp:287] Recovering containerizer
I0807 19:42:11.907052 1129 slave.cpp:3175] Finished recovery
I0807 19:42:11.907282 1129 slave.cpp:589] New master detected at master@140.211.11.27:45707
I0807 19:42:11.907305 1129 slave.cpp:663] Authenticating with master master@140.211.11.27:45707
I0807 19:42:11.907346 1129 slave.cpp:636] Detecting new master
I0807 19:42:11.907380 1129 status_update_manager.cpp:167] New master detected at master@140.211.11.27:45707
I0807 19:42:11.907414 1129 authenticatee.hpp:128] Creating new client SASL connection
I0807 19:42:11.907549 1129 master.cpp:3615] Authenticating slave(200)@140.211.11.27:45707
I0807 19:42:11.907629 1129 authenticator.hpp:156] Creating new server SASL connection
I0807 19:42:11.907717 1129 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0807 19:42:11.907733 1129 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0807 19:42:11.907758 1129 authenticator.hpp:262] Received SASL authentication start
I0807 19:42:11.907796 1129 authenticator.hpp:384] Authentication requires more steps
I0807 19:42:11.907821 1129 authenticatee.hpp:265] Received SASL authentication step
I0807 19:42:11.907855 1129 authenticator.hpp:290] Received SASL authentication step
I0807 19:42:11.907868 1129 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0807 19:42:11.907876 1129 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0807 19:42:11.907886 1129 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0807 19:42:11.907893 1129 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0807 19:42:11.907901 1129 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0807 19:42:11.907906 1129 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0807 19:42:11.907915 1129 authenticator.hpp:376] Authentication success
I0807 19:42:11.907940 1129 authenticatee.hpp:305] Authentication success
I0807 19:42:11.907961 1129 master.cpp:3655] Successfully authenticated principal 'test-principal' at slave(200)@140.211.11.27:45707
I0807 19:42:11.908025 1129 slave.cpp:720] Successfully authenticated with master master@140.211.11.27:45707
I0807 19:42:11.908058 1129 slave.cpp:971] Will retry registration in 1.664128ms if necessary
I0807 19:42:11.908121 1129 master.cpp:2837] Registering slave at slave(200)@140.211.11.27:45707 (hemera.apache.org) with id 20140807-194211-453759884-45707-32388-0
I0807 19:42:11.908226 1129 registrar.cpp:422] Attempting to update the 'registry'
I0807 19:42:11.909888 1116 log.cpp:680] Attempting to append 332 bytes to the log
I0807 19:42:11.909940 1116 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0807 19:42:11.910162 1116 replica.cpp:508] Replica received write request for position 3
I0807 19:42:11.910842 1129 slave.cpp:971] Will retry registration in 34.48304ms if necessary
I0807 19:42:11.910943 1115 master.cpp:2825] Ignoring register slave message from slave(200)@140.211.11.27:45707 (hemera.apache.org) as admission is already in progress
I0807 19:42:11.925658 1116 leveldb.cpp:343] Persisting action (351 bytes) to leveldb took 15.479735ms
I0807 19:42:11.925685 1116 replica.cpp:676] Persisted action at 3
I0807 19:42:11.925947 1116 replica.cpp:655] Replica received learned notice for position 3
I0807 19:42:11.941659 1116 leveldb.cpp:343] Persisting action (353 bytes) to leveldb took 15.694454ms
I0807 19:42:11.941684 1116 replica.cpp:676] Persisted action at 3
I0807 19:42:11.941692 1116 replica.cpp:661] Replica learned APPEND action at position 3
I0807 19:42:11.941995 1116 registrar.cpp:479] Successfully updated 'registry'
I0807 19:42:11.942069 1116 log.cpp:699] Attempting to truncate the log to 3
I0807 19:42:11.942121 1116 master.cpp:2877] Registered slave 20140807-194211-453759884-45707-32388-0 at slave(200)@140.211.11.27:45707 (hemera.apache.org)
I0807 19:42:11.942133 1116 master.cpp:4088] Adding slave 20140807-194211-453759884-45707-32388-0 at slave(200)@140.211.11.27:45707 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0807 19:42:11.942230 1116 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0807 19:42:11.942309 1116 slave.cpp:754] Registered with master master@140.211.11.27:45707; given slave ID 20140807-194211-453759884-45707-32388-0
I0807 19:42:11.942381 1116 hierarchical_allocator_process.hpp:439] Added slave 20140807-194211-453759884-45707-32388-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0807 19:42:11.942417 1116 hierarchical_allocator_process.hpp:670] Performed allocation for slave 20140807-194211-453759884-45707-32388-0 in 8186ns
I0807 19:42:11.942469 1116 slave.cpp:2324] Received ping from slave-observer(171)@140.211.11.27:45707
I0807 19:42:11.942662 1116 replica.cpp:508] Replica received write request for position 4
I0807 19:42:11.942811 32388 master.cpp:634] Master terminating
I0807 19:42:11.945116 1152 slave.cpp:2356] master@140.211.11.27:45707 exited
W0807 19:42:11.945137 1152 slave.cpp:2359] Master disconnected! Waiting for a new master to be elected
I0807 19:42:11.960372 1116 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 17.665436ms
I0807 19:42:11.960398 1116 replica.cpp:676] Persisted action at 4
I0807 19:42:11.973811 32388 slave.cpp:466] Slave terminating
[ OK ] CredentialsTest.authenticatedSlaveText (380 ms)
[----------] 2 tests from CredentialsTest (792 ms total)
[----------] Global test environment tear-down
[==========] 359 tests from 57 test cases ran. (336278 ms total)
[ PASSED ] 358 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] AuthenticationTest.LeaderElectionDuringSlaveAuthentication
1 FAILED TEST
YOU HAVE 3 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make[1]: *** [check] Error 2
make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src'
make: *** [check-recursive] Error 1
Build step 'Execute shell' marked build as failure