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
