You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Yan Xu (JIRA)" <ji...@apache.org> on 2014/06/23 20:52:26 UTC
[jira] [Created] (MESOS-1532)
AllocatorZooKeeperTest/0.SlaveReregistersFirst is flaky
Yan Xu created MESOS-1532:
-----------------------------
Summary: AllocatorZooKeeperTest/0.SlaveReregistersFirst is flaky
Key: MESOS-1532
URL: https://issues.apache.org/jira/browse/MESOS-1532
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 0.20.0
Reporter: Yan Xu
{noformat:title=error}
tests/allocator_zookeeper_tests.cpp:105: Failure
Mock function called more times than expected - returning directly.
Function call: statusUpdate(0x7fff498ab9c0, @0x2b2864099960 80-byte object <10-3D 7A-44 28-2B 00-00 00-00 00-00 00-00 00-00 D0-74 09-64 28-2B 00-00 38-E1 EC-00 00-00 00-00 38-E1 EC-00 00-00 00-00 50-89 06-64 28-2B 00-00 01-00 00-00 00-2B 00-00 00-00 00-00 00-00 00-00 B8-B1 4F-3C 45-E9 D4-41 00-00 00-00 53-00 00-00>)
Expected: to be called once
Actual: called twice - over-saturated and active
{noformat}
{noformat:title=full log}
[ RUN ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst
Using temporary directory '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg'
I0620 22:12:29.007104 15771 leveldb.cpp:176] Opened db in 28.48695ms
I0620 22:12:29.016083 15771 leveldb.cpp:183] Compacted db in 8.803847ms
I0620 22:12:29.016229 15771 leveldb.cpp:198] Created db iterator in 5304ns
I0620 22:12:29.016473 15771 leveldb.cpp:204] Seeked to beginning of db in 1280ns
I0620 22:12:29.016600 15771 leveldb.cpp:273] Iterated through 0 keys in the db in 578ns
I0620 22:12:29.016762 15771 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,017:15771(0x2b2846e4a700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x18174e0 flags=0
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,017:15771(0x2b284704b700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b285c017ae0 flags=0
I0620 22:12:29.018342 15790 log.cpp:238] Attempting to join replica to ZooKeeper group
I0620 22:12:29.018507 15790 recover.cpp:425] Starting replica recovery
I0620 22:12:29.018589 15790 recover.cpp:451] Replica is in EMPTY status
I0620 22:12:29.018929 15790 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0620 22:12:29.018998 15790 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0620 22:12:29.019119 15790 recover.cpp:542] Updating replica status to STARTING
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,020:15771(0x2b284744d700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2848016e20 flags=0
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,021:15771(0x2b284724c700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2850012730 flags=0
I0620 22:12:29.023833 15791 master.cpp:286] Master 20140620-221229-16842879-59864-15771 (precise) started on 127.0.1.1:59864
I0620 22:12:29.023854 15791 master.cpp:323] Master only allowing authenticated frameworks to register
I0620 22:12:29.023859 15791 master.cpp:328] Master only allowing authenticated slaves to register
I0620 22:12:29.023865 15791 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg/credentials'
I0620 22:12:29.023928 15791 master.cpp:354] Authorization enabled
I0620 22:12:29.024602 15797 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:59864
I0620 22:12:29.025117 15791 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0620 22:12:29.025365 15791 contender.cpp:131] Joining the ZK group
2014-06-20 22:12:29,027:15771(0x2b2872ce8700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
I0620 22:12:29.028792 15790 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 9.608722ms
I0620 22:12:29.029295 15790 replica.cpp:320] Persisted replica status to STARTING
2014-06-20 22:12:29,029:15771(0x2b28730fe700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
2014-06-20 22:12:29,029:15771(0x2b2873500700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
I0620 22:12:29.029839 15790 recover.cpp:451] Replica is in STARTING status
I0620 22:12:29.030402 15790 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0620 22:12:29.030474 15790 recover.cpp:188] Received a recover response from a replica in STARTING status
I0620 22:12:29.030580 15790 recover.cpp:542] Updating replica status to VOTING
2014-06-20 22:12:29,031:15771(0x2b28726e5700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
I0620 22:12:29.047937 15790 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 17.297949ms
I0620 22:12:29.047969 15790 replica.cpp:320] Persisted replica status to VOTING
I0620 22:12:29.048028 15790 recover.cpp:556] Successfully joined the Paxos group
I0620 22:12:29.048099 15790 recover.cpp:440] Recover process terminated
2014-06-20 22:12:29,049:15771(0x2b2872ce8700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300000, negotiated timeout=10000
I0620 22:12:29.050029 15796 group.cpp:313] Group process (group(9)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.050048 15796 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0620 22:12:29.050056 15796 group.cpp:385] Trying to create path '/znode' in ZooKeeper
2014-06-20 22:12:29,055:15771(0x2b28730fe700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300001, negotiated timeout=10000
I0620 22:12:29.055445 15792 group.cpp:313] Group process (group(8)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.055462 15792 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0620 22:12:29.055469 15792 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
2014-06-20 22:12:29,056:15771(0x2b2873500700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300002, negotiated timeout=10000
I0620 22:12:29.056419 15791 group.cpp:313] Group process (group(10)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.056437 15791 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0620 22:12:29.056443 15791 group.cpp:385] Trying to create path '/znode' in ZooKeeper
2014-06-20 22:12:29,059:15771(0x2b28726e5700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300003, negotiated timeout=10000
I0620 22:12:29.060379 15793 group.cpp:313] Group process (group(7)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.060397 15793 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0620 22:12:29.060405 15793 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
I0620 22:12:29.075984 15794 contender.cpp:247] New candidate (id='0') has entered the contest for leadership
I0620 22:12:29.082536 15791 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.082630 15791 detector.cpp:138] Detected a new leader: (id='0')
I0620 22:12:29.083112 15797 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
I0620 22:12:29.084436 15796 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.096356 15797 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
I0620 22:12:29.096423 15797 master.cpp:1077] The newly elected leader is master@127.0.1.1:59864 with id 20140620-221229-16842879-59864-15771
I0620 22:12:29.096436 15797 master.cpp:1090] Elected as the leading master!
I0620 22:12:29.096443 15797 master.cpp:908] Recovering from registrar
I0620 22:12:29.096518 15797 registrar.cpp:313] Recovering registrar
I0620 22:12:29.096776 15797 log.cpp:656] Attempting to start the writer
I0620 22:12:29.097087 15797 replica.cpp:474] Replica received implicit promise request with proposal 1
I0620 22:12:29.097465 15793 network.hpp:423] ZooKeeper group memberships changed
I0620 22:12:29.097839 15793 group.cpp:658] Trying to get '/znode/log_replicas/0000000000' in ZooKeeper
I0620 22:12:29.099242 15793 network.hpp:461] ZooKeeper group PIDs: { log-replica(185)@127.0.1.1:59864 }
I0620 22:12:29.107118 15797 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 10.002873ms
I0620 22:12:29.107157 15797 replica.cpp:342] Persisted promised to 1
I0620 22:12:29.107345 15797 coordinator.cpp:230] Coordinator attemping to fill missing position
I0620 22:12:29.107666 15797 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0620 22:12:29.116905 15797 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 9.215833ms
I0620 22:12:29.116940 15797 replica.cpp:676] Persisted action at 0
I0620 22:12:29.117200 15797 replica.cpp:508] Replica received write request for position 0
I0620 22:12:29.117228 15797 leveldb.cpp:438] Reading position from leveldb took 13095ns
I0620 22:12:29.127976 15797 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 10.728783ms
I0620 22:12:29.128164 15797 replica.cpp:676] Persisted action at 0
I0620 22:12:29.133956 15790 replica.cpp:655] Replica received learned notice for position 0
I0620 22:12:29.142964 15790 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 8.975834ms
I0620 22:12:29.143003 15790 replica.cpp:676] Persisted action at 0
I0620 22:12:29.143014 15790 replica.cpp:661] Replica learned NOP action at position 0
I0620 22:12:29.143213 15790 log.cpp:672] Writer started with ending position 0
I0620 22:12:29.143463 15790 leveldb.cpp:438] Reading position from leveldb took 15413ns
I0620 22:12:29.149883 15790 registrar.cpp:346] Successfully fetched the registry (0B)
I0620 22:12:29.149911 15790 registrar.cpp:422] Attempting to update the 'registry'
I0620 22:12:29.151124 15790 log.cpp:680] Attempting to append 120 bytes to the log
I0620 22:12:29.151171 15790 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0620 22:12:29.151393 15790 replica.cpp:508] Replica received write request for position 1
I0620 22:12:29.160166 15790 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 8.747107ms
I0620 22:12:29.160344 15790 replica.cpp:676] Persisted action at 1
I0620 22:12:29.165982 15796 replica.cpp:655] Replica received learned notice for position 1
I0620 22:12:29.175163 15796 leveldb.cpp:343] Persisting action (139 bytes) to leveldb took 9.15178ms
I0620 22:12:29.175201 15796 replica.cpp:676] Persisted action at 1
I0620 22:12:29.175211 15796 replica.cpp:661] Replica learned APPEND action at position 1
I0620 22:12:29.175534 15796 registrar.cpp:479] Successfully updated 'registry'
I0620 22:12:29.175575 15796 registrar.cpp:372] Successfully recovered registrar
I0620 22:12:29.175613 15796 log.cpp:699] Attempting to truncate the log to 1
I0620 22:12:29.175686 15796 master.cpp:935] Recovered 0 slaves from the Registry (84B) ; allowing 10mins for slaves to re-register
I0620 22:12:29.175726 15796 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0620 22:12:29.175963 15796 replica.cpp:508] Replica received write request for position 2
I0620 22:12:29.179386 15771 sched.cpp:139] Version: 0.20.0
2014-06-20 22:12:29,179:15771(0x2b2846847700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,180:15771(0x2b2846847700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b284c0620a0 flags=0
2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,180:15771(0x2b284764e700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,181:15771(0x2b284764e700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2864062580 flags=0
I0620 22:12:29.179656 15795 slave.cpp:165] Slave started on 29)@127.0.1.1:59864
I0620 22:12:29.181361 15795 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_jFdang/credential'
I0620 22:12:29.181431 15795 slave.cpp:265] Slave using credential for: test-principal
I0620 22:12:29.181566 15795 slave.cpp:278] Slave resources: cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]
I0620 22:12:29.181632 15795 slave.cpp:306] Slave hostname: precise
I0620 22:12:29.181643 15795 slave.cpp:307] Slave checkpoint: false
I0620 22:12:29.182442 15795 state.cpp:33] Recovering state from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_jFdang/meta'
I0620 22:12:29.182555 15795 status_update_manager.cpp:193] Recovering status update manager
I0620 22:12:29.182664 15795 slave.cpp:3112] Finished recovery
2014-06-20 22:12:29,184:15771(0x2b2874343700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
I0620 22:12:29.185120 15796 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 9.136002ms
I0620 22:12:29.185309 15796 replica.cpp:676] Persisted action at 2
I0620 22:12:29.185518 15796 replica.cpp:655] Replica received learned notice for position 2
2014-06-20 22:12:29,186:15771(0x2b2873f41700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
2014-06-20 22:12:29,190:15771(0x2b2874343700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300004, negotiated timeout=10000
I0620 22:12:29.191119 15795 group.cpp:313] Group process (group(12)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.191140 15795 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0620 22:12:29.191148 15795 group.cpp:385] Trying to create path '/znode' in ZooKeeper
I0620 22:12:29.198513 15796 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 12.972967ms
I0620 22:12:29.198580 15796 leveldb.cpp:401] Deleting ~1 keys from leveldb took 30909ns
I0620 22:12:29.198593 15796 replica.cpp:676] Persisted action at 2
I0620 22:12:29.198603 15796 replica.cpp:661] Replica learned TRUNCATE action at position 2
2014-06-20 22:12:29,205:15771(0x2b2873f41700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300005, negotiated timeout=10000
I0620 22:12:29.206363 15796 group.cpp:313] Group process (group(11)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.206383 15796 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0620 22:12:29.206390 15796 group.cpp:385] Trying to create path '/znode' in ZooKeeper
I0620 22:12:29.207442 15795 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.207512 15795 detector.cpp:138] Detected a new leader: (id='0')
I0620 22:12:29.207624 15795 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
I0620 22:12:29.209198 15795 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
I0620 22:12:29.209259 15795 sched.cpp:235] New master detected at master@127.0.1.1:59864
I0620 22:12:29.209275 15795 sched.cpp:285] Authenticating with master master@127.0.1.1:59864
I0620 22:12:29.209381 15795 authenticatee.hpp:128] Creating new client SASL connection
I0620 22:12:29.209568 15795 master.cpp:3457] Authenticating scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:29.209663 15795 authenticator.hpp:156] Creating new server SASL connection
I0620 22:12:29.209835 15795 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0620 22:12:29.209853 15795 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0620 22:12:29.209877 15795 authenticator.hpp:262] Received SASL authentication start
I0620 22:12:29.209923 15795 authenticator.hpp:384] Authentication requires more steps
I0620 22:12:29.209947 15795 authenticatee.hpp:265] Received SASL authentication step
I0620 22:12:29.209980 15795 authenticator.hpp:290] Received SASL authentication step
I0620 22:12:29.210003 15795 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0620 22:12:29.210011 15795 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0620 22:12:29.210021 15795 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0620 22:12:29.210029 15795 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0620 22:12:29.210034 15795 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:29.210038 15795 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:29.210049 15795 authenticator.hpp:376] Authentication success
I0620 22:12:29.210074 15795 authenticatee.hpp:305] Authentication success
I0620 22:12:29.210095 15795 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:29.210160 15795 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:59864
I0620 22:12:29.210172 15795 sched.cpp:478] Sending registration request to master@127.0.1.1:59864
I0620 22:12:29.210229 15795 master.cpp:1196] Received registration request from scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:29.210250 15795 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0620 22:12:29.210372 15795 master.cpp:1255] Registering framework 20140620-221229-16842879-59864-15771-0000 at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:29.210469 15795 sched.cpp:409] Framework registered with 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.210489 15795 sched.cpp:423] Scheduler::registered took 8462ns
I0620 22:12:29.210521 15795 hierarchical_allocator_process.hpp:331] Added framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.210530 15795 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0620 22:12:29.210536 15795 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 5801ns
I0620 22:12:29.211791 15796 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.211848 15796 detector.cpp:138] Detected a new leader: (id='0')
I0620 22:12:29.211936 15796 group.cpp:658] Trying to get '/znode/info_0000000000' in ZooKeeper
I0620 22:12:29.212857 15796 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
I0620 22:12:29.212914 15796 slave.cpp:581] New master detected at master@127.0.1.1:59864
I0620 22:12:29.212936 15796 slave.cpp:657] Authenticating with master master@127.0.1.1:59864
I0620 22:12:29.212971 15796 slave.cpp:630] Detecting new master
I0620 22:12:29.213006 15796 status_update_manager.cpp:167] New master detected at master@127.0.1.1:59864
I0620 22:12:29.213034 15796 authenticatee.hpp:128] Creating new client SASL connection
I0620 22:12:29.213161 15796 master.cpp:3457] Authenticating slave(29)@127.0.1.1:59864
I0620 22:12:29.213234 15796 authenticator.hpp:156] Creating new server SASL connection
I0620 22:12:29.213328 15796 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0620 22:12:29.213345 15796 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0620 22:12:29.213366 15796 authenticator.hpp:262] Received SASL authentication start
I0620 22:12:29.213397 15796 authenticator.hpp:384] Authentication requires more steps
I0620 22:12:29.213420 15796 authenticatee.hpp:265] Received SASL authentication step
I0620 22:12:29.213448 15796 authenticator.hpp:290] Received SASL authentication step
I0620 22:12:29.213460 15796 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0620 22:12:29.213466 15796 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0620 22:12:29.213474 15796 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0620 22:12:29.213481 15796 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0620 22:12:29.213487 15796 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:29.213491 15796 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:29.213500 15796 authenticator.hpp:376] Authentication success
I0620 22:12:29.213523 15796 authenticatee.hpp:305] Authentication success
I0620 22:12:29.213543 15796 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(29)@127.0.1.1:59864
I0620 22:12:29.213600 15796 slave.cpp:714] Successfully authenticated with master master@127.0.1.1:59864
I0620 22:12:29.213650 15796 slave.cpp:952] Will retry registration in 16.997934ms if necessary
I0620 22:12:29.214143 15794 master.cpp:2736] Registering slave at slave(29)@127.0.1.1:59864 (precise) with id 20140620-221229-16842879-59864-15771-0
I0620 22:12:29.214293 15794 registrar.cpp:422] Attempting to update the 'registry'
I0620 22:12:29.215993 15793 log.cpp:680] Attempting to append 295 bytes to the log
I0620 22:12:29.216048 15793 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0620 22:12:29.216550 15793 replica.cpp:508] Replica received write request for position 3
I0620 22:12:29.225689 15793 leveldb.cpp:343] Persisting action (314 bytes) to leveldb took 9.110879ms
I0620 22:12:29.225765 15793 replica.cpp:676] Persisted action at 3
I0620 22:12:29.225973 15793 replica.cpp:655] Replica received learned notice for position 3
I0620 22:12:29.231385 15791 slave.cpp:952] Will retry registration in 39.831813ms if necessary
I0620 22:12:29.231457 15791 master.cpp:2724] Ignoring register slave message from slave(29)@127.0.1.1:59864 (precise) as admission is already in progress
I0620 22:12:29.234421 15793 leveldb.cpp:343] Persisting action (316 bytes) to leveldb took 8.425837ms
I0620 22:12:29.234449 15793 replica.cpp:676] Persisted action at 3
I0620 22:12:29.234458 15793 replica.cpp:661] Replica learned APPEND action at position 3
I0620 22:12:29.234796 15793 registrar.cpp:479] Successfully updated 'registry'
I0620 22:12:29.234876 15793 log.cpp:699] Attempting to truncate the log to 3
I0620 22:12:29.234933 15793 master.cpp:2776] Registered slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
I0620 22:12:29.234947 15793 master.cpp:3923] Adding slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]
I0620 22:12:29.235056 15793 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0620 22:12:29.235136 15793 slave.cpp:748] Registered with master master@127.0.1.1:59864; given slave ID 20140620-221229-16842879-59864-15771-0
I0620 22:12:29.235203 15793 hierarchical_allocator_process.hpp:444] Added slave 20140620-221229-16842879-59864-15771-0 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] available)
I0620 22:12:29.235267 15793 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 to framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.235359 15793 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140620-221229-16842879-59864-15771-0 in 126210ns
I0620 22:12:29.235460 15793 master.hpp:789] Adding offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
I0620 22:12:29.235501 15793 master.cpp:3404] Sending 1 offers to framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.235810 15793 sched.cpp:546] Scheduler::resourceOffers took 181453ns
I0620 22:12:29.236023 15793 master.hpp:799] Removing offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
I0620 22:12:29.236073 15793 master.cpp:2080] Processing reply for offers: [ 20140620-221229-16842879-59864-15771-0 ] on slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) for framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.236101 15793 master.cpp:2166] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
I0620 22:12:29.236491 15793 master.hpp:761] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
I0620 22:12:29.236518 15793 master.cpp:2232] Launching task 0 of framework 20140620-221229-16842879-59864-15771-0000 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
I0620 22:12:29.236650 15793 replica.cpp:508] Replica received write request for position 4
I0620 22:12:29.236804 15791 slave.cpp:983] Got assigned task 0 for framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.236945 15792 hierarchical_allocator_process.hpp:546] Framework 20140620-221229-16842879-59864-15771-0000 left cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] unused on slave 20140620-221229-16842879-59864-15771-0
I0620 22:12:29.237021 15792 hierarchical_allocator_process.hpp:588] Framework 20140620-221229-16842879-59864-15771-0000 filtered slave 20140620-221229-16842879-59864-15771-0 for 5secs
I0620 22:12:29.237287 15791 slave.cpp:1093] Launching task 0 for framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.240905 15791 exec.cpp:131] Version: 0.20.0
I0620 22:12:29.241333 15790 exec.cpp:181] Executor started at: executor(1)@127.0.1.1:59864 with pid 15771
I0620 22:12:29.241606 15791 slave.cpp:1203] Queuing task '0' for executor default of framework '20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.241992 15791 slave.cpp:542] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_jFdang/slaves/20140620-221229-16842879-59864-15771-0/frameworks/20140620-221229-16842879-59864-15771-0000/executors/default/runs/1b52f316-bf41-4c84-b875-bbbe336b91fa'
I0620 22:12:29.242290 15791 slave.cpp:1714] Got registration for executor 'default' of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.242789 15792 exec.cpp:205] Executor registered on slave 20140620-221229-16842879-59864-15771-0
I0620 22:12:29.244197 15792 exec.cpp:217] Executor::registered took 30105ns
I0620 22:12:29.244571 15791 slave.cpp:1833] Flushing queued task 0 for executor 'default' of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.245123 15795 exec.cpp:292] Executor asked to run task '0'
I0620 22:12:29.245187 15795 exec.cpp:301] Executor::launchTask took 45150ns
I0620 22:12:29.246320 15795 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.246585 15791 slave.cpp:2449] Monitoring executor 'default' of framework '20140620-221229-16842879-59864-15771-0000' in container '1b52f316-bf41-4c84-b875-bbbe336b91fa'
I0620 22:12:29.247234 15791 slave.cpp:2068] Handling status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 from executor(1)@127.0.1.1:59864
I0620 22:12:29.247689 15792 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.247714 15792 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.247827 15792 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to master@127.0.1.1:59864
I0620 22:12:29.248124 15792 master.cpp:3062] Status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 from slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
I0620 22:12:29.248641 15792 master.cpp:610] Master terminating
I0620 22:12:29.248975 15792 master.hpp:779] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
I0620 22:12:29.248380 15794 sched.cpp:637] Scheduler::statusUpdate took 30965ns
W0620 22:12:29.249487 15792 master.cpp:4209] Removing task 0 of framework 20140620-221229-16842879-59864-15771-0000 and slave 20140620-221229-16842879-59864-15771-0 in non-terminal state TASK_RUNNING
I0620 22:12:29.249703 15794 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]) on slave 20140620-221229-16842879-59864-15771-0 from framework 20140620-221229-16842879-59864-15771-0000
2014-06-20 22:12:29,251:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300001 to [127.0.0.1:42843]
2014-06-20 22:12:29,253:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300003 to [127.0.0.1:42843]
I0620 22:12:29.255873 15793 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 19.142912ms
I0620 22:12:29.256362 15793 replica.cpp:676] Persisted action at 4
I0620 22:12:29.259801 15771 contender.cpp:186] Now cancelling the membership: 0
2014-06-20 22:12:29,260:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300000 to [127.0.0.1:42843]
2014-06-20 22:12:29,260:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300002 to [127.0.0.1:42843]
I0620 22:12:29.263706 15791 slave.cpp:2311] master@127.0.1.1:59864 exited
W0620 22:12:29.264472 15791 slave.cpp:2314] Master disconnected! Waiting for a new master to be elected
I0620 22:12:29.264873 15791 slave.cpp:2226] Status update manager successfully handled status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.265123 15791 slave.cpp:2232] Sending acknowledgement for status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to executor(1)@127.0.1.1:59864
I0620 22:12:29.265492 15790 exec.cpp:338] Executor received status update acknowledgement 132905cf-168a-48a5-9ad5-5381463e2e6e for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.276870 15792 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.277102 15792 detector.cpp:126] The current leader (id=0) is lost
I0620 22:12:29.277117 15792 detector.cpp:138] Detected a new leader: None
I0620 22:12:29.277495 15795 slave.cpp:626] Lost leading master
I0620 22:12:29.277513 15795 slave.cpp:630] Detecting new master
I0620 22:12:29.278142 15797 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.278192 15797 detector.cpp:126] The current leader (id=0) is lost
I0620 22:12:29.278200 15797 detector.cpp:138] Detected a new leader: None
I0620 22:12:29.278306 15797 sched.cpp:229] Scheduler::disconnected took 7760ns
I0620 22:12:29.278318 15797 sched.cpp:251] No master detected
I0620 22:12:29.291004 15771 leveldb.cpp:176] Opened db in 29.746546ms
I0620 22:12:29.307518 15771 leveldb.cpp:183] Compacted db in 16.068905ms
I0620 22:12:29.307977 15771 leveldb.cpp:198] Created db iterator in 7322ns
I0620 22:12:29.308254 15771 leveldb.cpp:204] Seeked to beginning of db in 12436ns
I0620 22:12:29.308590 15771 leveldb.cpp:273] Iterated through 5 keys in the db in 60139ns
I0620 22:12:29.308857 15771 replica.cpp:741] Replica recovered with log positions 1 -> 4 with 0 holes and 1 unlearned
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,309:15771(0x2b2846847700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b2864066890 flags=0
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,310:15771(0x2b2846c49700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b28600471a0 flags=0
I0620 22:12:29.311206 15791 log.cpp:238] Attempting to join replica to ZooKeeper group
I0620 22:12:29.312000 15791 recover.cpp:425] Starting replica recovery
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,312:15771(0x2b2846a48700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b286800dbb0 flags=0
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@716: Client environment:host.name=precise
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@723: Client environment:os.name=Linux
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@724: Client environment:os.arch=3.2.0-64-generic
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@725: Client environment:os.version=#97-Ubuntu SMP Wed Jun 4 22:04:21 UTC 2014
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@733: Client environment:user.name=(null)
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg
2014-06-20 22:12:29,312:15771(0x2b284744d700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:42843 sessionTimeout=10000 watcher=0x2b2843e8f6f0 sessionId=0 sessionPasswd=<null> context=0x2b286801c8c0 flags=0
I0620 22:12:29.312999 15797 recover.cpp:451] Replica is in VOTING status
I0620 22:12:29.313045 15797 recover.cpp:440] Recover process terminated
I0620 22:12:29.313536 15795 master.cpp:286] Master 20140620-221229-16842879-59864-15771 (precise) started on 127.0.1.1:59864
I0620 22:12:29.313559 15795 master.cpp:323] Master only allowing authenticated frameworks to register
I0620 22:12:29.313565 15795 master.cpp:328] Master only allowing authenticated slaves to register
I0620 22:12:29.313571 15795 credentials.hpp:35] Loading credentials for authentication from '/tmp/AllocatorZooKeeperTest_0_FrameworkReregistersFirst_Cr5GZg/credentials'
I0620 22:12:29.313642 15795 master.cpp:354] Authorization enabled
I0620 22:12:29.314226 15795 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0620 22:12:29.314483 15795 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@127.0.1.1:59864
I0620 22:12:29.314532 15795 contender.cpp:131] Joining the ZK group
2014-06-20 22:12:29,315:15771(0x2b2872efd700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
2014-06-20 22:12:29,316:15771(0x2b2872ae7700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
2014-06-20 22:12:29,317:15771(0x2b28728e6700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
2014-06-20 22:12:29,321:15771(0x2b28732ff700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:42843]
2014-06-20 22:12:29,323:15771(0x2b2872efd700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300006, negotiated timeout=10000
I0620 22:12:29.324039 15795 group.cpp:313] Group process (group(16)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.324064 15795 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0620 22:12:29.324071 15795 group.cpp:385] Trying to create path '/znode' in ZooKeeper
2014-06-20 22:12:29,327:15771(0x2b2872ae7700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300007, negotiated timeout=10000
I0620 22:12:29.328102 15797 group.cpp:313] Group process (group(15)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.328124 15797 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0620 22:12:29.328130 15797 group.cpp:385] Trying to create path '/znode' in ZooKeeper
2014-06-20 22:12:29,328:15771(0x2b28728e6700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300008, negotiated timeout=10000
I0620 22:12:29.328908 15792 group.cpp:313] Group process (group(14)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.328927 15792 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0620 22:12:29.328933 15792 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
2014-06-20 22:12:29,341:15771(0x2b28732ff700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:42843], sessionId=0x146bcd70e300009, negotiated timeout=10000
I0620 22:12:29.342126 15795 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.342445 15796 group.cpp:313] Group process (group(13)@127.0.1.1:59864) connected to ZooKeeper
I0620 22:12:29.342464 15796 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0620 22:12:29.342473 15796 group.cpp:385] Trying to create path '/znode/log_replicas' in ZooKeeper
I0620 22:12:29.363756 15795 contender.cpp:247] New candidate (id='2') has entered the contest for leadership
I0620 22:12:29.365463 15796 network.hpp:423] ZooKeeper group memberships changed
I0620 22:12:29.365558 15796 group.cpp:658] Trying to get '/znode/log_replicas/0000000001' in ZooKeeper
I0620 22:12:29.366583 15791 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.366644 15791 detector.cpp:138] Detected a new leader: (id='2')
I0620 22:12:29.367019 15791 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
I0620 22:12:29.367941 15794 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.367998 15794 detector.cpp:138] Detected a new leader: (id='2')
I0620 22:12:29.368088 15794 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
I0620 22:12:29.369071 15790 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.369397 15790 detector.cpp:138] Detected a new leader: (id='2')
I0620 22:12:29.369505 15790 group.cpp:658] Trying to get '/znode/info_0000000002' in ZooKeeper
I0620 22:12:29.370779 15797 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:29.371628 15796 network.hpp:461] ZooKeeper group PIDs: { log-replica(186)@127.0.1.1:59864 }
I0620 22:12:29.372532 15791 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
I0620 22:12:29.372588 15791 master.cpp:1077] The newly elected leader is master@127.0.1.1:59864 with id 20140620-221229-16842879-59864-15771
I0620 22:12:29.372601 15791 master.cpp:1090] Elected as the leading master!
I0620 22:12:29.372607 15791 master.cpp:908] Recovering from registrar
I0620 22:12:29.372665 15791 registrar.cpp:313] Recovering registrar
I0620 22:12:29.372895 15791 log.cpp:656] Attempting to start the writer
I0620 22:12:29.373225 15791 replica.cpp:474] Replica received implicit promise request with proposal 2
I0620 22:12:29.374613 15794 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
I0620 22:12:29.374676 15794 sched.cpp:235] New master detected at master@127.0.1.1:59864
I0620 22:12:29.374692 15794 sched.cpp:285] Authenticating with master master@127.0.1.1:59864
I0620 22:12:29.374776 15794 authenticatee.hpp:128] Creating new client SASL connection
I0620 22:12:29.374933 15794 master.cpp:817] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
I0620 22:12:29.375727 15790 detector.cpp:382] A new leading master (UPID=master@127.0.1.1:59864) is detected
I0620 22:12:29.375789 15790 slave.cpp:581] New master detected at master@127.0.1.1:59864
I0620 22:12:29.375810 15790 slave.cpp:657] Authenticating with master master@127.0.1.1:59864
I0620 22:12:29.375845 15790 slave.cpp:630] Detecting new master
I0620 22:12:29.375882 15790 status_update_manager.cpp:167] New master detected at master@127.0.1.1:59864
W0620 22:12:29.375896 15790 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:29.375908 15790 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to master@127.0.1.1:59864
I0620 22:12:29.375970 15790 authenticatee.hpp:128] Creating new client SASL connection
I0620 22:12:29.376078 15790 master.cpp:817] Dropping 'mesos.internal.StatusUpdateMessage' message since not recovered yet
I0620 22:12:29.376097 15790 master.cpp:817] Dropping 'mesos.internal.AuthenticateMessage' message since not recovered yet
I0620 22:12:29.379063 15791 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.809509ms
I0620 22:12:29.379096 15791 replica.cpp:342] Persisted promised to 2
I0620 22:12:29.379273 15791 coordinator.cpp:230] Coordinator attemping to fill missing position
I0620 22:12:29.379658 15791 replica.cpp:375] Replica received explicit promise request for position 4 with proposal 3
I0620 22:12:29.379705 15791 leveldb.cpp:438] Reading position from leveldb took 29411ns
I0620 22:12:29.384661 15791 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 4.936565ms
I0620 22:12:29.384819 15791 replica.cpp:676] Persisted action at 4
I0620 22:12:29.385390 15791 replica.cpp:508] Replica received write request for position 4
I0620 22:12:29.385659 15791 leveldb.cpp:438] Reading position from leveldb took 15704ns
I0620 22:12:29.390548 15791 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 4.680333ms
I0620 22:12:29.391034 15791 replica.cpp:676] Persisted action at 4
I0620 22:12:29.391342 15791 replica.cpp:655] Replica received learned notice for position 4
I0620 22:12:29.396769 15791 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 5.390672ms
I0620 22:12:29.397305 15791 leveldb.cpp:401] Deleting ~2 keys from leveldb took 33015ns
I0620 22:12:29.397632 15791 replica.cpp:676] Persisted action at 4
I0620 22:12:29.398012 15791 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0620 22:12:29.401564 15796 log.cpp:672] Writer started with ending position 4
I0620 22:12:29.401896 15796 leveldb.cpp:438] Reading position from leveldb took 30936ns
I0620 22:12:29.401921 15796 leveldb.cpp:438] Reading position from leveldb took 5786ns
I0620 22:12:29.402222 15796 registrar.cpp:346] Successfully fetched the registry (256B)
I0620 22:12:29.402256 15796 registrar.cpp:422] Attempting to update the 'registry'
I0620 22:12:29.403610 15796 log.cpp:680] Attempting to append 295 bytes to the log
I0620 22:12:29.403653 15796 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5
I0620 22:12:29.403854 15796 replica.cpp:508] Replica received write request for position 5
I0620 22:12:29.408926 15796 leveldb.cpp:343] Persisting action (314 bytes) to leveldb took 5.050337ms
I0620 22:12:29.409181 15796 replica.cpp:676] Persisted action at 5
I0620 22:12:29.413992 15790 replica.cpp:655] Replica received learned notice for position 5
I0620 22:12:29.419201 15790 leveldb.cpp:343] Persisting action (316 bytes) to leveldb took 5.1782ms
I0620 22:12:29.419237 15790 replica.cpp:676] Persisted action at 5
I0620 22:12:29.419247 15790 replica.cpp:661] Replica learned APPEND action at position 5
I0620 22:12:29.419589 15790 registrar.cpp:479] Successfully updated 'registry'
I0620 22:12:29.419643 15790 registrar.cpp:372] Successfully recovered registrar
I0620 22:12:29.419711 15790 log.cpp:699] Attempting to truncate the log to 5
I0620 22:12:29.419816 15790 master.cpp:935] Recovered 1 slaves from the Registry (256B) ; allowing 10mins for slaves to re-register
I0620 22:12:29.419860 15790 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6
I0620 22:12:29.420567 15792 replica.cpp:508] Replica received write request for position 6
I0620 22:12:29.425196 15792 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 4.605186ms
I0620 22:12:29.425227 15792 replica.cpp:676] Persisted action at 6
I0620 22:12:29.425431 15792 replica.cpp:655] Replica received learned notice for position 6
I0620 22:12:29.430459 15792 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 5.007608ms
I0620 22:12:29.430516 15792 leveldb.cpp:401] Deleting ~2 keys from leveldb took 28852ns
I0620 22:12:29.430528 15792 replica.cpp:676] Persisted action at 6
I0620 22:12:29.430537 15792 replica.cpp:661] Replica learned TRUNCATE action at position 6
I0620 22:12:30.315253 15792 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0620 22:12:30.315289 15792 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 51725ns
I0620 22:12:31.315965 15792 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0620 22:12:31.316007 15792 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 49055ns
I0620 22:12:32.316705 15792 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0620 22:12:32.317195 15792 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 493999ns
I0620 22:12:33.318656 15793 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0620 22:12:33.318692 15793 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 83759ns
I0620 22:12:34.315120 15791 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0620 22:12:34.319368 15791 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0620 22:12:34.319385 15791 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 18776ns
W0620 22:12:34.375746 15791 sched.cpp:380] Authentication timed out
I0620 22:12:34.375829 15791 sched.cpp:340] Failed to authenticate with master master@127.0.1.1:59864: Authentication discarded
I0620 22:12:34.375870 15791 sched.cpp:285] Authenticating with master master@127.0.1.1:59864
I0620 22:12:34.375943 15791 authenticatee.hpp:128] Creating new client SASL connection
I0620 22:12:34.376127 15791 master.cpp:3457] Authenticating scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:34.376214 15791 authenticator.hpp:156] Creating new server SASL connection
I0620 22:12:34.376317 15791 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0620 22:12:34.376335 15791 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0620 22:12:34.376358 15791 authenticator.hpp:262] Received SASL authentication start
I0620 22:12:34.376406 15791 authenticator.hpp:384] Authentication requires more steps
I0620 22:12:34.376431 15791 authenticatee.hpp:265] Received SASL authentication step
I0620 22:12:34.376463 15791 authenticator.hpp:290] Received SASL authentication step
I0620 22:12:34.376477 15791 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0620 22:12:34.376484 15791 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0620 22:12:34.376494 15791 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0620 22:12:34.376502 15791 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0620 22:12:34.376508 15791 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:34.376513 15791 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:34.376523 15791 authenticator.hpp:376] Authentication success
I0620 22:12:34.376548 15791 authenticatee.hpp:305] Authentication success
I0620 22:12:34.376569 15791 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:34.376631 15791 sched.cpp:359] Successfully authenticated with master master@127.0.1.1:59864
I0620 22:12:34.376644 15791 sched.cpp:478] Sending registration request to master@127.0.1.1:59864
I0620 22:12:34.376694 15791 master.cpp:1304] Received re-registration request from framework 20140620-221229-16842879-59864-15771-0000 at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:34.376714 15791 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0620 22:12:34.376831 15791 master.cpp:1355] Re-registering framework 20140620-221229-16842879-59864-15771-0000 at scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
I0620 22:12:34.376931 15791 sched.cpp:409] Framework registered with 20140620-221229-16842879-59864-15771-0000
I0620 22:12:34.376953 15791 sched.cpp:423] Scheduler::registered took 8487ns
I0620 22:12:34.377058 15791 hierarchical_allocator_process.hpp:331] Added framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:34.377068 15791 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0620 22:12:34.377074 15791 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 5932ns
W0620 22:12:34.377575 15793 slave.cpp:731] Authentication timed out
W0620 22:12:34.377624 15793 slave.cpp:695] Failed to authenticate with master master@127.0.1.1:59864: Authentication discarded
I0620 22:12:34.377641 15793 slave.cpp:657] Authenticating with master master@127.0.1.1:59864
I0620 22:12:34.377686 15793 authenticatee.hpp:128] Creating new client SASL connection
I0620 22:12:34.377854 15793 master.cpp:3457] Authenticating slave(29)@127.0.1.1:59864
I0620 22:12:34.377923 15793 authenticator.hpp:156] Creating new server SASL connection
I0620 22:12:34.378015 15793 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0620 22:12:34.378031 15793 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0620 22:12:34.378047 15793 authenticator.hpp:262] Received SASL authentication start
I0620 22:12:34.378077 15793 authenticator.hpp:384] Authentication requires more steps
I0620 22:12:34.378094 15793 authenticatee.hpp:265] Received SASL authentication step
I0620 22:12:34.378115 15793 authenticator.hpp:290] Received SASL authentication step
I0620 22:12:34.378128 15793 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0620 22:12:34.378134 15793 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0620 22:12:34.378141 15793 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0620 22:12:34.378149 15793 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'precise' server FQDN: 'precise' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0620 22:12:34.378154 15793 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:34.378159 15793 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0620 22:12:34.378168 15793 authenticator.hpp:376] Authentication success
I0620 22:12:34.378183 15793 authenticatee.hpp:305] Authentication success
I0620 22:12:34.378196 15793 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(29)@127.0.1.1:59864
I0620 22:12:34.378340 15795 slave.cpp:714] Successfully authenticated with master master@127.0.1.1:59864
I0620 22:12:34.378454 15795 slave.cpp:952] Will retry registration in 2.31379ms if necessary
I0620 22:12:34.378617 15793 master.cpp:2911] Re-registering slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
I0620 22:12:34.378770 15793 registrar.cpp:422] Attempting to update the 'registry'
I0620 22:12:34.380069 15793 log.cpp:680] Attempting to append 295 bytes to the log
I0620 22:12:34.380113 15793 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 7
I0620 22:12:34.380283 15793 replica.cpp:508] Replica received write request for position 7
I0620 22:12:34.382016 15797 slave.cpp:952] Will retry registration in 17.58087ms if necessary
I0620 22:12:34.382084 15797 master.cpp:2904] Ignoring re-register slave message from slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) as readmission is already in progress
I0620 22:12:34.386593 15793 leveldb.cpp:343] Persisting action (314 bytes) to leveldb took 6.289188ms
I0620 22:12:34.386939 15793 replica.cpp:676] Persisted action at 7
I0620 22:12:34.393925 15790 replica.cpp:655] Replica received learned notice for position 7
I0620 22:12:34.399257 15790 leveldb.cpp:343] Persisting action (316 bytes) to leveldb took 5.306209ms
I0620 22:12:34.399286 15790 replica.cpp:676] Persisted action at 7
I0620 22:12:34.399296 15790 replica.cpp:661] Replica learned APPEND action at position 7
I0620 22:12:34.399574 15790 registrar.cpp:479] Successfully updated 'registry'
I0620 22:12:34.399675 15790 log.cpp:699] Attempting to truncate the log to 7
I0620 22:12:34.399732 15790 master.cpp:2962] Re-registered slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
I0620 22:12:34.399762 15790 master.cpp:3923] Adding slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000]
I0620 22:12:34.399864 15790 master.hpp:761] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
I0620 22:12:34.399976 15790 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 8
I0620 22:12:34.400038 15790 slave.cpp:798] Re-registered with master master@127.0.1.1:59864
I0620 22:12:34.400080 15790 slave.cpp:1564] Updating framework 20140620-221229-16842879-59864-15771-0000 pid to scheduler-3d720a51-c2cb-4670-a37e-1fe811c53a07@127.0.1.1:59864
W0620 22:12:34.400223 15790 status_update_manager.cpp:181] Resending status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:34.400243 15790 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to master@127.0.1.1:59864
I0620 22:12:34.400337 15790 hierarchical_allocator_process.hpp:444] Added slave 20140620-221229-16842879-59864-15771-0 (precise) with cpus(*):2; mem(*):1024; disk(*):25116; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] available)
I0620 22:12:34.400392 15790 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 to framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:34.400475 15790 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140620-221229-16842879-59864-15771-0 in 106278ns
I0620 22:12:34.400557 15790 master.cpp:3062] Status update TASK_RUNNING (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000 from slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
I0620 22:12:34.400612 15790 master.hpp:789] Adding offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
I0620 22:12:34.400650 15790 master.cpp:3404] Sending 1 offers to framework 20140620-221229-16842879-59864-15771-0000
tests/allocator_zookeeper_tests.cpp:105: Failure
Mock function called more times than expected - returning directly.
Function call: statusUpdate(0x7fff498ab9c0, @0x2b2864099960 80-byte object <10-3D 7A-44 28-2B 00-00 00-00 00-00 00-00 00-00 D0-74 09-64 28-2B 00-00 38-E1 EC-00 00-00 00-00 38-E1 EC-00 00-00 00-00 50-89 06-64 28-2B 00-00 01-00 00-00 00-2B 00-00 00-00 00-00 00-00 00-00 B8-B1 4F-3C 45-E9 D4-41 00-00 00-00 53-00 00-00>)
Expected: to be called once
Actual: called twice - over-saturated and active
I0620 22:12:34.400858 15790 sched.cpp:637] Scheduler::statusUpdate took 134984ns
I0620 22:12:34.400949 15790 sched.cpp:546] Scheduler::resourceOffers took 18763ns
I0620 22:12:34.401028 15790 master.cpp:2586] Forwarding status update acknowledgement 132905cf-168a-48a5-9ad5-5381463e2e6e for task 0 of framework 20140620-221229-16842879-59864-15771-0000 to slave 20140620-221229-16842879-59864-15771-0 at slave(29)@127.0.1.1:59864 (precise)
I0620 22:12:34.401201 15796 replica.cpp:508] Replica received write request for position 8
I0620 22:12:34.401298 15792 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:34.401882 15792 slave.cpp:1654] Status update manager successfully handled status update acknowledgement (UUID: 132905cf-168a-48a5-9ad5-5381463e2e6e) for task 0 of framework 20140620-221229-16842879-59864-15771-0000
I0620 22:12:34.402114 15771 master.cpp:610] Master terminating
I0620 22:12:34.402158 15771 master.hpp:779] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 20140620-221229-16842879-59864-15771-0 (precise)
W0620 22:12:34.402195 15771 master.cpp:4209] Removing task 0 of framework 20140620-221229-16842879-59864-15771-0000 and slave 20140620-221229-16842879-59864-15771-0 in non-terminal state TASK_RUNNING
I0620 22:12:34.402242 15771 master.hpp:799] Removing offer 20140620-221229-16842879-59864-15771-0 with resources cpus(*):1; mem(*):524; disk(*):25116; ports(*):[31000-32000] on slave 20140620-221229-16842879-59864-15771-0 (precise)
I0620 22:12:34.402901 15791 sched.cpp:747] Stopping framework '20140620-221229-16842879-59864-15771-0000'
I0620 22:12:34.403477 15792 slave.cpp:2311] master@127.0.1.1:59864 exited
W0620 22:12:34.403494 15792 slave.cpp:2314] Master disconnected! Waiting for a new master to be elected
2014-06-20 22:12:34,403:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300008 to [127.0.0.1:42843]
2014-06-20 22:12:34,405:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300009 to [127.0.0.1:42843]
I0620 22:12:34.406445 15796 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.218772ms
I0620 22:12:34.406472 15796 replica.cpp:676] Persisted action at 8
I0620 22:12:34.409512 15771 contender.cpp:186] Now cancelling the membership: 2
I0620 22:12:34.409955 15792 group.cpp:619] Trying to remove '/znode/info_0000000002' in ZooKeeper
2014-06-20 22:12:34,414:15771(0x2b2846a48700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300007 to [127.0.0.1:42843]
I0620 22:12:34.420526 15793 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:34.420570 15793 detector.cpp:126] The current leader (id=2) is lost
I0620 22:12:34.420579 15793 detector.cpp:138] Detected a new leader: None
I0620 22:12:34.420655 15793 slave.cpp:626] Lost leading master
I0620 22:12:34.420665 15793 slave.cpp:630] Detecting new master
I0620 22:12:34.420735 15794 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:34.420766 15794 detector.cpp:126] The current leader (id=2) is lost
I0620 22:12:34.420774 15794 detector.cpp:138] Detected a new leader: None
I0620 22:12:34.420862 15796 group.cpp:714] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper
I0620 22:12:34.420893 15796 detector.cpp:126] The current leader (id=2) is lost
I0620 22:12:34.420902 15796 detector.cpp:138] Detected a new leader: None
2014-06-20 22:12:34,426:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300006 to [127.0.0.1:42843]
I0620 22:12:34.426604 15771 slave.cpp:466] Slave terminating
I0620 22:12:34.426631 15771 slave.cpp:1387] Asked to shut down framework 20140620-221229-16842879-59864-15771-0000 by @0.0.0.0:0
W0620 22:12:34.426641 15771 slave.cpp:1395] Ignoring shutdown framework message for 20140620-221229-16842879-59864-15771-0000 because the slave has not yet registered with the master
2014-06-20 22:12:34,427:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300005 to [127.0.0.1:42843]
2014-06-20 22:12:34,427:15771(0x2b2846641f80):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x146bcd70e300004 to [127.0.0.1:42843]
[ FAILED ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> (5456 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)