[MESOS-2407] libprocess segfaults when using GLOG_v=2 - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: None
Component/s: None
Labels:
None

Description

Found this while debugging ~~MESOS-2403~~. Looks like a thread safety issue with stream operator in Process::resume().

[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from MasterAllocatorTest/0, where TypeParam = mesos::internal::master::allocator::MesosAllocator<mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> >
[ RUN      ] MasterAllocatorTest/0.FrameworkReregistersFirst
I0226 00:48:28.159126 29931 process.cpp:2150] Spawned process files@10.35.255.108:46621
I0226 00:48:28.159194 29958 process.cpp:2160] Resuming files@10.35.255.108:46621 at 2015-02-26 00:48:28.159184896+00:00
I0226 00:48:28.159333 29958 process.cpp:2160] Resuming help@10.35.255.108:46621 at 2015-02-26 00:48:28.159284992+00:00
I0226 00:48:28.159343 29931 process.cpp:2150] Spawned process hierarchical-allocator(25)@10.35.255.108:46621
I0226 00:48:28.159418 29955 process.cpp:2160] Resuming hierarchical-allocator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.159364864+00:00
Using temporary directory '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_J8P9UO'
I0226 00:48:28.165838 29970 process.cpp:2117] Dropped / Lost event for PID: hierarchical-allocator(22)@10.35.255.108:46621
I0226 00:48:28.193131 29964 process.cpp:2160] Resuming reaper(1)@10.35.255.108:46621 at 2015-02-26 00:48:28.193116928+00:00
I0226 00:48:28.267730 29931 leveldb.cpp:176] Opened db in 107.694932ms
I0226 00:48:28.281376 29931 leveldb.cpp:183] Compacted db in 13.598726ms
I0226 00:48:28.281435 29931 leveldb.cpp:198] Created db iterator in 10363ns
I0226 00:48:28.281461 29931 leveldb.cpp:204] Seeked to beginning of db in 1180ns
I0226 00:48:28.281491 29931 leveldb.cpp:273] Iterated through 0 keys in the db in 328ns
I0226 00:48:28.281518 29931 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0226 00:48:28.281559 29931 process.cpp:2150] Spawned process log-replica(25)@10.35.255.108:46621
I0226 00:48:28.281648 29959 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.281634048+00:00
I0226 00:48:28.281716 29967 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.281709056+00:00
I0226 00:48:28.281654 29931 process.cpp:2150] Spawned process (257)@10.35.255.108:46621
I0226 00:48:28.281837 29931 process.cpp:2150] Spawned process log(25)@10.35.255.108:46621
I0226 00:48:28.281843 29962 process.cpp:2160] Resuming log(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.281829120+00:00
I0226 00:48:28.282060 29931 process.cpp:2150] Spawned process log-reader(25)@10.35.255.108:46621
I0226 00:48:28.282080 29948 process.cpp:2160] Resuming log-reader(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.282066944+00:00
I0226 00:48:28.282142 29962 process.cpp:2150] Spawned process log-recover(25)@10.35.255.108:46621
I0226 00:48:28.282181 29962 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.282177024+00:00
I0226 00:48:28.282162 29952 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.282151936+00:00
I0226 00:48:28.282162 29958 process.cpp:2160] Resuming log-recover(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.282151936+00:00
I0226 00:48:28.282378 29958 recover.cpp:449] Starting replica recovery
I0226 00:48:28.282438 29954 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.282430976+00:00
I0226 00:48:28.282512 29931 process.cpp:2150] Spawned process log-writer(25)@10.35.255.108:46621
I0226 00:48:28.282533 29968 process.cpp:2160] Resuming log-recover(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.282522880+00:00
I0226 00:48:28.282591 29968 recover.cpp:475] Replica is in 4 status
I0226 00:48:28.282618 29950 process.cpp:2160] Resuming metrics@10.35.255.108:46621 at 2015-02-26 00:48:28.282608128+00:00
I0226 00:48:28.282716 29963 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.282684928+00:00
I0226 00:48:28.282769 29951 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.282759936+00:00
I0226 00:48:28.282693 29931 process.cpp:2150] Spawned process (258)@10.35.255.108:46621
I0226 00:48:28.282898 29968 process.cpp:2150] Spawned process log-recover-protocol(25)@10.35.255.108:46621
I0226 00:48:28.282961 29952 process.cpp:2160] Resuming registrar(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.282951168+00:00
I0226 00:48:28.282968 29965 process.cpp:2160] Resuming metrics@10.35.255.108:46621 at 2015-02-26 00:48:28.282906112+00:00
I0226 00:48:28.282904 29967 process.cpp:2160] Resuming log-recover-protocol(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.282897920+00:00
I0226 00:48:28.283108 29965 process.cpp:2160] Resuming help@10.35.255.108:46621 at 2015-02-26 00:48:28.283099904+00:00
I0226 00:48:28.283139 29967 recover.cpp:131] Starting to wait for enough quorum of replicas before running recovery protocol, expected quroum size: 1
I0226 00:48:28.282938 29931 process.cpp:2150] Spawned process registrar(25)@10.35.255.108:46621
I0226 00:48:28.283241 29949 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.283233024+00:00
I0226 00:48:28.283210 29967 process.cpp:2150] Spawned process __latch__(254)@10.35.255.108:46621
I0226 00:48:28.283309 29960 process.cpp:2160] Resuming __latch__(254)@10.35.255.108:46621 at 2015-02-26 00:48:28.283233792+00:00
I0226 00:48:28.283306 29968 process.cpp:2160] Resuming standalone-master-detector(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.283265024+00:00
I0226 00:48:28.283305 29950 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.283226112+00:00
I0226 00:48:28.283257 29931 process.cpp:2150] Spawned process standalone-master-detector(49)@10.35.255.108:46621
I0226 00:48:28.283561 29931 process.cpp:2150] Spawned process authorizer(25)@10.35.255.108:46621
I0226 00:48:28.283568 29966 process.cpp:2160] Resuming log-recover-protocol(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.283526912+00:00
I0226 00:48:28.283583 29952 process.cpp:2160] Resuming authorizer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.283575040+00:00
I0226 00:48:28.283643 29966 recover.cpp:145] Broadcasting recover request to all replicas
I0226 00:48:28.283742 29958 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.283734016+00:00
I0226 00:48:28.283746 29969 process.cpp:2160] Resuming metrics@10.35.255.108:46621 at 2015-02-26 00:48:28.283740160+00:00
I0226 00:48:28.283871 29958 process.cpp:2150] Spawned process (259)@10.35.255.108:46621
I0226 00:48:28.283912 29963 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.283892992+00:00
I0226 00:48:28.283912 29947 process.cpp:2160] Resuming (259)@10.35.255.108:46621 at 2015-02-26 00:48:28.283892992+00:00
I0226 00:48:28.283999 29959 process.cpp:2160] Resuming log-recover-protocol(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.283984896+00:00
I0226 00:48:28.284140 29953 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.284132864+00:00
I0226 00:48:28.284205 29959 recover.cpp:154] Broadcast request completed
I0226 00:48:28.284337 29953 replica.cpp:641] Replica in 4 status received a broadcasted recover request
I0226 00:48:28.284334 29947 process.cpp:2160] Resuming standalone-master-detector(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.284326144+00:00
I0226 00:48:28.284708 29931 process.cpp:2150] Spawned process master@10.35.255.108:46621
I0226 00:48:28.284714 29952 process.cpp:2160] Resuming (259)@10.35.255.108:46621 at 2015-02-26 00:48:28.284696064+00:00
I0226 00:48:28.284757 29948 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.284744960+00:00
I0226 00:48:28.284775 29931 process.cpp:2150] Spawned process __latch__(255)@10.35.255.108:46621
I0226 00:48:28.284785 29969 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.284776960+00:00
I0226 00:48:28.284814 29931 process.cpp:2150] Spawned process __waiter__(74)@10.35.255.108:46621
I0226 00:48:28.284803 29948 master.cpp:349] Master 20150226-004828-1828659978-46621-29931 (smfd-atr-11-sr1.devel.twitter.com) started on 10.35.255.108:46621
I0226 00:48:28.284827 29951 process.cpp:2160] Resuming log-recover-protocol(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.284819968+00:00
I0226 00:48:28.284837 29960 process.cpp:2160] Resuming __waiter__(74)@10.35.255.108:46621 at 2015-02-26 00:48:28.284827904+00:00
I0226 00:48:28.284827 29952 process.cpp:2267] Cleaning up (259)@10.35.255.108:46621
I0226 00:48:28.284785 29965 process.cpp:2160] Resuming __latch__(255)@10.35.255.108:46621 at 2015-02-26 00:48:28.284780032+00:00
I0226 00:48:28.284992 29948 master.cpp:395] Master only allowing authenticated frameworks to register
I0226 00:48:28.285006 29951 recover.cpp:195] Received a recover response from a replica in 4 status
I0226 00:48:28.285064 29952 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.285060864+00:00
I0226 00:48:28.285101 29948 master.cpp:400] Master only allowing authenticated slaves to register
I0226 00:48:28.285166 29948 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_J8P9UO/credentials'
I0226 00:48:28.285179 29957 process.cpp:2160] Resuming __latch__(254)@10.35.255.108:46621 at 2015-02-26 00:48:28.285132800+00:00
I0226 00:48:28.285203 29951 process.cpp:2267] Cleaning up log-recover-protocol(25)@10.35.255.108:46621
I0226 00:48:28.285203 29954 process.cpp:2160] Resuming log-recover(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.285198080+00:00
I0226 00:48:28.285223 29957 process.cpp:2267] Cleaning up __latch__(254)@10.35.255.108:46621
I0226 00:48:28.285254 29954 recover.cpp:566] Updating replica status to 3
I0226 00:48:28.285244 29951 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.285240832+00:00
I0226 00:48:28.285384 29954 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.285299968+00:00
I0226 00:48:28.285447 29948 master.cpp:442] Authorization enabled
I0226 00:48:28.285636 29948 process.cpp:2150] Spawned process whitelist(25)@10.35.255.108:46621
I0226 00:48:28.285663 29956 process.cpp:2160] Resuming hierarchical-allocator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.285650944+00:00
I0226 00:48:28.285689 29959 process.cpp:2160] Resuming whitelist(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.285680128+00:00
I0226 00:48:28.285737 29959 whitelist_watcher.cpp:79] No whitelist given
I0226 00:48:28.285742 29960 process.cpp:2160] Resuming help@10.35.255.108:46621 at 2015-02-26 00:48:28.285728000+00:00
I0226 00:48:28.285835 29956 hierarchical.hpp:287] Initialized hierarchical allocator process
I0226 00:48:28.285874 29956 process.cpp:2160] Resuming standalone-master-detector(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.285871872+00:00
I0226 00:48:28.285962 29956 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.285958144+00:00
I0226 00:48:28.286021 29956 master.cpp:1356] The newly elected leader is master@10.35.255.108:46621 with id 20150226-004828-1828659978-46621-29931
I0226 00:48:28.286053 29956 master.cpp:1369] Elected as the leading master!
I0226 00:48:28.286077 29956 master.cpp:1187] Recovering from registrar
I0226 00:48:28.286363 29952 process.cpp:2160] Resuming registrar(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.286343168+00:00
I0226 00:48:28.286375 29964 process.cpp:2160] Resuming standalone-master-detector(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.286362880+00:00
I0226 00:48:28.286450 29952 registrar.cpp:313] Recovering registrar
I0226 00:48:28.286510 29952 process.cpp:2150] Spawned process __latch__(256)@10.35.255.108:46621
I0226 00:48:28.286501 29963 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.286493952+00:00
I0226 00:48:28.286695 29963 log.cpp:224] Starting the writer
I0226 00:48:28.286521 29962 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.286513152+00:00
I0226 00:48:28.286523 29961 process.cpp:2160] Resuming __latch__(256)@10.35.255.108:46621 at 2015-02-26 00:48:28.286513152+00:00
I0226 00:48:28.286869 29965 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.286861056+00:00
I0226 00:48:28.293534 29963 process.cpp:2160] Resuming reaper(1)@10.35.255.108:46621 at 2015-02-26 00:48:28.293487104+00:00
I0226 00:48:28.343099 29954 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 57.658801ms
I0226 00:48:28.343164 29954 replica.cpp:323] Persisted replica status to 3
I0226 00:48:28.343226 29954 process.cpp:2160] Resuming log-recover(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.343219968+00:00
I0226 00:48:28.343327 29954 recover.cpp:475] Replica is in 3 status
I0226 00:48:28.343377 29954 process.cpp:2150] Spawned process log-recover-protocol(26)@10.35.255.108:46621
I0226 00:48:28.343411 29954 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.343408128+00:00
I0226 00:48:28.343447 29961 process.cpp:2160] Resuming log-recover-protocol(26)@10.35.255.108:46621 at 2015-02-26 00:48:28.343439104+00:00
I0226 00:48:28.343493 29961 recover.cpp:131] Starting to wait for enough quorum of replicas before running recovery protocol, expected quroum size: 1
I0226 00:48:28.343544 29961 process.cpp:2150] Spawned process __latch__(257)@10.35.255.108:46621
I0226 00:48:28.343590 29961 process.cpp:2160] Resuming __latch__(257)@10.35.255.108:46621 at 2015-02-26 00:48:28.343588096+00:00
I0226 00:48:28.343704 29956 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.343588096+00:00
I0226 00:48:28.343704 29958 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.343588096+00:00
I0226 00:48:28.344136 29958 process.cpp:2160] Resuming log-recover-protocol(26)@10.35.255.108:46621 at 2015-02-26 00:48:28.344103936+00:00
I0226 00:48:28.344228 29958 recover.cpp:145] Broadcasting recover request to all replicas
I0226 00:48:28.344281 29961 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.344270080+00:00
I0226 00:48:28.344377 29961 process.cpp:2150] Spawned process (260)@10.35.255.108:46621
I0226 00:48:28.344411 29949 process.cpp:2160] Resuming (260)@10.35.255.108:46621 at 2015-02-26 00:48:28.344404992+00:00
I0226 00:48:28.344408 29946 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.344397056+00:00
I0226 00:48:28.344480 29961 process.cpp:2160] Resuming log-recover-protocol(26)@10.35.255.108:46621 at 2015-02-26 00:48:28.344471808+00:00
I0226 00:48:28.344596 29968 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.344582144+00:00
I0226 00:48:28.344698 29961 recover.cpp:154] Broadcast request completed
I0226 00:48:28.344854 29968 replica.cpp:641] Replica in 3 status received a broadcasted recover request
I0226 00:48:28.344888 29968 process.cpp:2160] Resuming (260)@10.35.255.108:46621 at 2015-02-26 00:48:28.344886016+00:00
I0226 00:48:28.344940 29968 process.cpp:2267] Cleaning up (260)@10.35.255.108:46621
I0226 00:48:28.344949 29953 process.cpp:2160] Resuming log-recover-protocol(26)@10.35.255.108:46621 at 2015-02-26 00:48:28.344935936+00:00
I0226 00:48:28.345101 29968 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.345097984+00:00
I0226 00:48:28.345121 29953 recover.cpp:195] Received a recover response from a replica in 3 status
I0226 00:48:28.345545 29953 process.cpp:2267] Cleaning up log-recover-protocol(26)@10.35.255.108:46621
I0226 00:48:28.345612 29952 process.cpp:2160] Resuming log-recover(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.345603840+00:00
I0226 00:48:28.345795 29953 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.345710080+00:00
I0226 00:48:28.345800 29952 recover.cpp:566] Updating replica status to 1
I0226 00:48:28.345612 29962 process.cpp:2160] Resuming __latch__(257)@10.35.255.108:46621 at 2015-02-26 00:48:28.345573888+00:00
I0226 00:48:28.346300 29946 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.346177024+00:00
I0226 00:48:28.346367 29962 process.cpp:2267] Cleaning up __latch__(257)@10.35.255.108:46621
I0226 00:48:28.346560 29962 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.346537216+00:00
I0226 00:48:28.360492 29946 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.062446ms
I0226 00:48:28.360551 29946 replica.cpp:323] Persisted replica status to 1
I0226 00:48:28.360630 29946 process.cpp:2160] Resuming log-recover(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.360603136+00:00
I0226 00:48:28.360677 29946 recover.cpp:580] Successfully joined the Paxos group
I0226 00:48:28.360735 29946 recover.cpp:464] Recover process terminated
I0226 00:48:28.360816 29946 process.cpp:2267] Cleaning up log-recover(25)@10.35.255.108:46621
I0226 00:48:28.360841 29949 process.cpp:2160] Resuming log(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.360805120+00:00
I0226 00:48:28.360934 29946 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.360850176+00:00
I0226 00:48:28.360982 29949 log.cpp:358] Log recovery completed
I0226 00:48:28.361201 29949 process.cpp:2160] Resuming log-reader(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.361196032+00:00
I0226 00:48:28.361246 29947 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.361198848+00:00
I0226 00:48:28.361639 29947 process.cpp:2150] Spawned process log-coordinator(25)@10.35.255.108:46621
I0226 00:48:28.361747 29947 log.cpp:660] Attempting to start the writer
I0226 00:48:28.361663 29955 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.361650944+00:00
I0226 00:48:28.361912 29962 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.361900032+00:00
I0226 00:48:28.362049 29960 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.362001920+00:00
I0226 00:48:28.362229 29960 process.cpp:2150] Spawned process log-implicit-promise(25)@10.35.255.108:46621
I0226 00:48:28.362264 29965 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.362235136+00:00
I0226 00:48:28.362272 29953 process.cpp:2160] Resuming log-implicit-promise(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.362243840+00:00
I0226 00:48:28.362489 29953 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.362444032+00:00
I0226 00:48:28.362603 29953 process.cpp:2160] Resuming log-implicit-promise(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.362585088+00:00
I0226 00:48:28.362738 29953 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.362735104+00:00
I0226 00:48:28.362838 29953 process.cpp:2150] Spawned process (261)@10.35.255.108:46621
I0226 00:48:28.362885 29953 process.cpp:2160] Resuming log-implicit-promise(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.362881024+00:00
I0226 00:48:28.362882 29957 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.362846976+00:00
I0226 00:48:28.362882 29967 process.cpp:2160] Resuming (261)@10.35.255.108:46621 at 2015-02-26 00:48:28.362846976+00:00
I0226 00:48:28.363378 29948 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.363323904+00:00
I0226 00:48:28.363440 29948 replica.cpp:477] Replica received implicit promise request with proposal 1
I0226 00:48:28.368865 29948 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.389715ms
I0226 00:48:28.368906 29948 replica.cpp:345] Persisted promised to 1
I0226 00:48:28.368944 29948 process.cpp:2160] Resuming (261)@10.35.255.108:46621 at 2015-02-26 00:48:28.368940032+00:00
I0226 00:48:28.369065 29948 process.cpp:2267] Cleaning up (261)@10.35.255.108:46621
I0226 00:48:28.369092 29948 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.369090048+00:00
I0226 00:48:28.369086 29950 process.cpp:2160] Resuming log-implicit-promise(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.369074944+00:00
I0226 00:48:28.369235 29950 process.cpp:2267] Cleaning up log-implicit-promise(25)@10.35.255.108:46621
I0226 00:48:28.369282 29961 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.369268992+00:00
I0226 00:48:28.369357 29963 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.369310976+00:00
I0226 00:48:28.369393 29953 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.369381888+00:00
I0226 00:48:28.369621 29953 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.369616128+00:00
I0226 00:48:28.369724 29953 coordinator.cpp:230] Coordinator attemping to fill missing position
I0226 00:48:28.369792 29964 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.369783040+00:00
I0226 00:48:28.369766 29953 process.cpp:2150] Spawned process log-bulk-catch-up(15)@10.35.255.108:46621
I0226 00:48:28.369796 29961 process.cpp:2160] Resuming log-bulk-catch-up(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.369787904+00:00
I0226 00:48:28.370069 29961 process.cpp:2150] Spawned process log-catch-up(15)@10.35.255.108:46621
I0226 00:48:28.370085 29963 process.cpp:2160] Resuming log-catch-up(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.370074112+00:00
I0226 00:48:28.370102 29954 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.370068992+00:00
I0226 00:48:28.370245 29949 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.370237952+00:00
I0226 00:48:28.370321 29949 process.cpp:2160] Resuming log-catch-up(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.370317056+00:00
I0226 00:48:28.370393 29949 process.cpp:2150] Spawned process log-fill(15)@10.35.255.108:46621
I0226 00:48:28.370507 29947 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.370402048+00:00
I0226 00:48:28.370507 29956 process.cpp:2160] Resuming log-fill(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.370402048+00:00
I0226 00:48:28.370765 29956 process.cpp:2150] Spawned process log-explicit-promise(15)@10.35.255.108:46621
I0226 00:48:28.370803 29958 process.cpp:2160] Resuming log-explicit-promise(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.370789120+00:00
I0226 00:48:28.370805 29951 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.370778112+00:00
I0226 00:48:28.371129 29958 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.371053824+00:00
I0226 00:48:28.371326 29964 process.cpp:2160] Resuming log-explicit-promise(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.371282176+00:00
I0226 00:48:28.371441 29964 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.371438080+00:00
I0226 00:48:28.371503 29964 process.cpp:2150] Spawned process (262)@10.35.255.108:46621
I0226 00:48:28.371508 29966 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.371501056+00:00
I0226 00:48:28.371568 29960 process.cpp:2160] Resuming log-explicit-promise(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.371560960+00:00
I0226 00:48:28.371559 29964 process.cpp:2160] Resuming (262)@10.35.255.108:46621 at 2015-02-26 00:48:28.371555072+00:00
I0226 00:48:28.371808 29964 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.371803136+00:00
I0226 00:48:28.371989 29964 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0226 00:48:28.377125 29964 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 5.096302ms
I0226 00:48:28.377181 29964 replica.cpp:679] Persisted action at 0
I0226 00:48:28.377226 29964 process.cpp:2160] Resuming (262)@10.35.255.108:46621 at 2015-02-26 00:48:28.377222912+00:00
I0226 00:48:28.377297 29964 process.cpp:2267] Cleaning up (262)@10.35.255.108:46621
I0226 00:48:28.377341 29949 process.cpp:2160] Resuming log-explicit-promise(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.377327872+00:00
I0226 00:48:28.377393 29959 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.377383936+00:00
I0226 00:48:28.377493 29949 process.cpp:2267] Cleaning up log-explicit-promise(15)@10.35.255.108:46621
I0226 00:48:28.377518 29959 process.cpp:2160] Resuming log-fill(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.377513984+00:00
I0226 00:48:28.377645 29953 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.377588992+00:00
I0226 00:48:28.377650 29959 process.cpp:2150] Spawned process log-write(111)@10.35.255.108:46621
I0226 00:48:28.377687 29946 process.cpp:2160] Resuming log-write(111)@10.35.255.108:46621 at 2015-02-26 00:48:28.377656832+00:00
I0226 00:48:28.377789 29947 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.377782016+00:00
I0226 00:48:28.377871 29953 process.cpp:2160] Resuming log-write(111)@10.35.255.108:46621 at 2015-02-26 00:48:28.377863936+00:00
I0226 00:48:28.378173 29953 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.378160896+00:00
I0226 00:48:28.378335 29967 process.cpp:2160] Resuming (263)@10.35.255.108:46621 at 2015-02-26 00:48:28.378323200+00:00
I0226 00:48:28.378365 29953 process.cpp:2150] Spawned process (263)@10.35.255.108:46621
I0226 00:48:28.378343 29959 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.378312960+00:00
I0226 00:48:28.378603 29965 process.cpp:2160] Resuming (263)@10.35.255.108:46621 at 2015-02-26 00:48:28.378588928+00:00
I0226 00:48:28.379011 29957 process.cpp:2160] Resuming log-write(111)@10.35.255.108:46621 at 2015-02-26 00:48:28.379002112+00:00
I0226 00:48:28.379017 29965 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.379010816+00:00
I0226 00:48:28.379122 29965 replica.cpp:511] Replica received write request for position 0
I0226 00:48:28.379161 29965 leveldb.cpp:438] Reading position from leveldb took 14399ns
I0226 00:48:28.379595 29970 process.cpp:2117] Dropped / Lost event for PID: (11)@10.35.255.108:46621
I0226 00:48:28.385501 29965 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 6.291929ms
I0226 00:48:28.385546 29965 replica.cpp:679] Persisted action at 0
I0226 00:48:28.385615 29965 process.cpp:2160] Resuming (263)@10.35.255.108:46621 at 2015-02-26 00:48:28.385584128+00:00
I0226 00:48:28.385684 29965 process.cpp:2267] Cleaning up (263)@10.35.255.108:46621
I0226 00:48:28.385725 29953 process.cpp:2160] Resuming log-write(111)@10.35.255.108:46621 at 2015-02-26 00:48:28.385680896+00:00
I0226 00:48:28.385771 29965 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.385762816+00:00
I0226 00:48:28.385881 29965 process.cpp:2160] Resuming log-fill(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.385875968+00:00
I0226 00:48:28.386070 29953 process.cpp:2267] Cleaning up log-write(111)@10.35.255.108:46621
I0226 00:48:28.386162 29958 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.386151936+00:00
I0226 00:48:28.386179 29959 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.386169856+00:00
I0226 00:48:28.386299 29953 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.386292992+00:00
I0226 00:48:28.386528 29953 replica.cpp:658] Replica received learned notice for position 0
I0226 00:48:28.386687 29966 process.cpp:2160] Resuming log-fill(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.386599168+00:00
I0226 00:48:28.386821 29966 process.cpp:2267] Cleaning up log-fill(15)@10.35.255.108:46621
I0226 00:48:28.386826 29952 process.cpp:2160] Resuming log-catch-up(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.386817024+00:00
I0226 00:48:28.386891 29966 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.386887168+00:00
I0226 00:48:28.393806 29953 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.233341ms
I0226 00:48:28.393880 29953 replica.cpp:679] Persisted action at 0
I0226 00:48:28.393916 29953 replica.cpp:664] Replica learned 1 action at position 0
I0226 00:48:28.393995 29964 process.cpp:2160] Resuming reaper(1)@10.35.255.108:46621 at 2015-02-26 00:48:28.393896960+00:00
I0226 00:48:28.394014 29953 process.cpp:2160] Resuming log-catch-up(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.393963008+00:00
I0226 00:48:28.394223 29960 process.cpp:2160] Resuming log-bulk-catch-up(15)@10.35.255.108:46621 at 2015-02-26 00:48:28.394212096+00:00
I0226 00:48:28.394212 29953 process.cpp:2267] Cleaning up log-catch-up(15)@10.35.255.108:46621
I0226 00:48:28.394533 29960 process.cpp:2267] Cleaning up log-bulk-catch-up(15)@10.35.255.108:46621
I0226 00:48:28.394552 29963 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.394542848+00:00
I0226 00:48:28.394925 29965 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.394903808+00:00
I0226 00:48:28.394996 29952 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.394982144+00:00
I0226 00:48:28.395164 29965 log.cpp:676] Writer started with ending position 0
I0226 00:48:28.395256 29965 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.395250944+00:00
I0226 00:48:28.395304 29965 log.cpp:245] Writer got elected at position 
I0226 00:48:28.395362 29965 process.cpp:2160] Resuming log-reader(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.395344896+00:00
I0226 00:48:28.395504 29961 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.395467008+00:00
I0226 00:48:28.395577 29956 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.395569152+00:00
I0226 00:48:28.395712 29956 process.cpp:2160] Resuming log-reader(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.395643904+00:00
I0226 00:48:28.395920 29953 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.395910144+00:00
I0226 00:48:28.396031 29953 replica.cpp:225] Starting read from '0' to '0'
I0226 00:48:28.396085 29953 leveldb.cpp:438] Reading position from leveldb took 14049ns
I0226 00:48:28.396157 29946 process.cpp:2160] Resuming log-reader(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.396148992+00:00
I0226 00:48:28.396337 29958 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.396256000+00:00
I0226 00:48:28.396427 29958 log.cpp:287] Applying operations (0 entries)
I0226 00:48:28.397629 29958 process.cpp:2160] Resuming __latch__(256)@10.35.255.108:46621 at 2015-02-26 00:48:28.397613056+00:00
I0226 00:48:28.397675 29958 process.cpp:2267] Cleaning up __latch__(256)@10.35.255.108:46621
I0226 00:48:28.397668 29946 process.cpp:2160] Resuming registrar(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.397646848+00:00
I0226 00:48:28.397727 29958 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.397713920+00:00
I0226 00:48:28.397795 29946 registrar.cpp:346] Successfully fetched the registry (0B) in 111.299072ms
I0226 00:48:28.397886 29946 registrar.cpp:445] Applied 1 operations in 2925ns; attempting to update the 'registry'
I0226 00:48:28.399137 29946 process.cpp:2150] Spawned process __latch__(258)@10.35.255.108:46621
I0226 00:48:28.399199 29953 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.399152128+00:00
I0226 00:48:28.399209 29946 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.399202048+00:00
I0226 00:48:28.399256 29956 process.cpp:2160] Resuming __latch__(258)@10.35.255.108:46621 at 2015-02-26 00:48:28.399207168+00:00
I0226 00:48:28.399370 29958 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.399355904+00:00
I0226 00:48:28.399559 29958 log.cpp:684] Attempting to append 155 bytes to the log
I0226 00:48:28.399708 29959 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.399624960+00:00
I0226 00:48:28.399770 29959 coordinator.cpp:340] Coordinator attempting to write 2 action at position 1
I0226 00:48:28.399827 29959 process.cpp:2150] Spawned process log-write(112)@10.35.255.108:46621
I0226 00:48:28.399828 29950 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.399821056+00:00
I0226 00:48:28.399837 29964 process.cpp:2160] Resuming log-write(112)@10.35.255.108:46621 at 2015-02-26 00:48:28.399830016+00:00
I0226 00:48:28.400090 29950 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.400084992+00:00
I0226 00:48:28.400239 29956 process.cpp:2160] Resuming log-write(112)@10.35.255.108:46621 at 2015-02-26 00:48:28.400228864+00:00
I0226 00:48:28.400395 29956 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.400388096+00:00
I0226 00:48:28.400506 29956 process.cpp:2150] Spawned process (264)@10.35.255.108:46621
I0226 00:48:28.400529 29946 process.cpp:2160] Resuming (264)@10.35.255.108:46621 at 2015-02-26 00:48:28.400517888+00:00
I0226 00:48:28.400537 29965 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.400513024+00:00
I0226 00:48:28.400624 29961 process.cpp:2160] Resuming log-write(112)@10.35.255.108:46621 at 2015-02-26 00:48:28.400573952+00:00
I0226 00:48:28.400650 29946 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.400641792+00:00
I0226 00:48:28.400701 29946 replica.cpp:511] Replica received write request for position 1
I0226 00:48:28.410470 29946 leveldb.cpp:343] Persisting action (174 bytes) to leveldb took 9.746931ms
I0226 00:48:28.410526 29946 replica.cpp:679] Persisted action at 1
I0226 00:48:28.410583 29946 process.cpp:2160] Resuming (264)@10.35.255.108:46621 at 2015-02-26 00:48:28.410577152+00:00
I0226 00:48:28.410662 29946 process.cpp:2267] Cleaning up (264)@10.35.255.108:46621
I0226 00:48:28.410681 29951 process.cpp:2160] Resuming log-write(112)@10.35.255.108:46621 at 2015-02-26 00:48:28.410665984+00:00
I0226 00:48:28.410804 29946 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.410733056+00:00
I0226 00:48:28.410851 29956 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.410828032+00:00
I0226 00:48:28.410825 29951 process.cpp:2267] Cleaning up log-write(112)@10.35.255.108:46621
I0226 00:48:28.411254 29968 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.411218944+00:00
I0226 00:48:28.411273 29956 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.411266048+00:00
I0226 00:48:28.411514 29954 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.411503104+00:00
I0226 00:48:28.411526 29956 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.411520000+00:00
I0226 00:48:28.411612 29954 replica.cpp:658] Replica received learned notice for position 1
I0226 00:48:28.418782 29954 leveldb.cpp:343] Persisting action (176 bytes) to leveldb took 7.073291ms
I0226 00:48:28.418838 29954 replica.cpp:679] Persisted action at 1
I0226 00:48:28.418869 29954 replica.cpp:664] Replica learned 2 action at position 1
I0226 00:48:28.418977 29954 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.418939136+00:00
I0226 00:48:28.419142 29968 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.419066880+00:00
I0226 00:48:28.419440 29948 process.cpp:2160] Resuming __latch__(258)@10.35.255.108:46621 at 2015-02-26 00:48:28.419426816+00:00
I0226 00:48:28.419510 29948 process.cpp:2267] Cleaning up __latch__(258)@10.35.255.108:46621
I0226 00:48:28.419502 29955 process.cpp:2160] Resuming registrar(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.419485184+00:00
I0226 00:48:28.419584 29955 registrar.cpp:490] Successfully updated the 'registry' in 21.638912ms
I0226 00:48:28.419703 29948 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.419693056+00:00
I0226 00:48:28.419730 29955 registrar.cpp:376] Successfully recovered registrar
I0226 00:48:28.419780 29956 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.419766016+00:00
I0226 00:48:28.419867 29949 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.419800064+00:00
I0226 00:48:28.419904 29956 master.cpp:1214] Recovered 0 slaves from the Registry (117B) ; allowing 10mins for slaves to re-register
I0226 00:48:28.419920 29951 process.cpp:2160] Resuming __latch__(255)@10.35.255.108:46621 at 2015-02-26 00:48:28.419895040+00:00
I0226 00:48:28.420192 29951 process.cpp:2267] Cleaning up __latch__(255)@10.35.255.108:46621
I0226 00:48:28.420053 29949 log.cpp:703] Attempting to truncate the log to 1
I0226 00:48:28.420269 29951 process.cpp:2160] Resuming __waiter__(74)@10.35.255.108:46621 at 2015-02-26 00:48:28.420265984+00:00
I0226 00:48:28.420326 29951 process.cpp:2267] Cleaning up __waiter__(74)@10.35.255.108:46621
I0226 00:48:28.420320 29949 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.420312832+00:00
I0226 00:48:28.420573 29949 coordinator.cpp:340] Coordinator attempting to write 3 action at position 2
I0226 00:48:28.420439 29931 clock.cpp:295] Clock paused at 0x28f44d0
I0226 00:48:28.420385 29957 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.420310016+00:00
I0226 00:48:28.420822 29949 clock.cpp:399] Clock of log-write(113)@10.35.255.108:46621 updated to 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.420912 29963 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.420908 29949 process.cpp:2150] Spawned process log-write(113)@10.35.255.108:46621
I0226 00:48:28.421015 29948 process.cpp:2160] Resuming log-write(113)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421371 29948 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421448 29948 process.cpp:2160] Resuming log-write(113)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421494 29948 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421527 29948 clock.cpp:399] Clock of (265)@10.35.255.108:46621 updated to 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421563 29948 process.cpp:2150] Spawned process (265)@10.35.255.108:46621
I0226 00:48:28.421576 29950 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421597 29969 process.cpp:2160] Resuming log-write(113)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421581 29963 process.cpp:2160] Resuming (265)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421847 29963 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.421965 29963 replica.cpp:511] Replica received write request for position 2
I0226 00:48:28.427124 29963 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.117128ms
I0226 00:48:28.427180 29963 replica.cpp:679] Persisted action at 2
I0226 00:48:28.427237 29963 process.cpp:2160] Resuming (265)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427335 29963 process.cpp:2267] Cleaning up (265)@10.35.255.108:46621
I0226 00:48:28.427389 29968 process.cpp:2160] Resuming log-write(113)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427413 29963 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427561 29968 process.cpp:2267] Cleaning up log-write(113)@10.35.255.108:46621
I0226 00:48:28.427553 29950 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427690 29968 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427775 29950 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427891 29950 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427920 29954 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.427958 29950 replica.cpp:658] Replica received learned notice for position 2
I0226 00:48:28.435438 29950 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.227579ms
I0226 00:48:28.435508 29950 leveldb.cpp:401] Deleting ~1 keys from leveldb took 21851ns
I0226 00:48:28.435541 29950 replica.cpp:679] Persisted action at 2
I0226 00:48:28.435570 29950 replica.cpp:664] Replica learned 3 action at position 2
I0226 00:48:28.435634 29953 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.435744 29968 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.420430848+00:00
I0226 00:48:28.441007 29931 clock.cpp:325] Clock resumed at 0x28fa090
I0226 00:48:28.442498 29931 process.cpp:2150] Spawned process standalone-master-detector(50)@10.35.255.108:46621
I0226 00:48:28.442512 29950 process.cpp:2160] Resuming standalone-master-detector(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.442503936+00:00
I0226 00:48:28.443287 29931 process.cpp:2150] Spawned process (266)@10.35.255.108:46621
I0226 00:48:28.443301 29955 process.cpp:2160] Resuming (266)@10.35.255.108:46621 at 2015-02-26 00:48:28.443293952+00:00
I0226 00:48:28.443454 29962 process.cpp:2160] Resuming (267)@10.35.255.108:46621 at 2015-02-26 00:48:28.443398912+00:00
I0226 00:48:28.443584 29931 process.cpp:2150] Spawned process (267)@10.35.255.108:46621
I0226 00:48:28.443832 29965 process.cpp:2160] Resuming metrics@10.35.255.108:46621 at 2015-02-26 00:48:28.443820032+00:00
I0226 00:48:28.443887 29931 process.cpp:2150] Spawned process __limiter__(14)@10.35.255.108:46621
I0226 00:48:28.443898 29962 process.cpp:2160] Resuming __limiter__(14)@10.35.255.108:46621 at 2015-02-26 00:48:28.443892992+00:00
I0226 00:48:28.444059 29931 process.cpp:2150] Spawned process monitor@10.35.255.108:46621
I0226 00:48:28.444077 29966 process.cpp:2160] Resuming monitor@10.35.255.108:46621 at 2015-02-26 00:48:28.444064000+00:00
I0226 00:48:28.444142 29949 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.444132096+00:00
I0226 00:48:28.444123 29931 process.cpp:2150] Spawned process slave(13)@10.35.255.108:46621
I0226 00:48:28.444389 29966 process.cpp:2160] Resuming help@10.35.255.108:46621 at 2015-02-26 00:48:28.444318976+00:00
I0226 00:48:28.444344 29949 slave.cpp:174] Slave started on 13)@10.35.255.108:46621
I0226 00:48:28.444519 29949 credentials.hpp:85] Loading credential for authentication from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_GFm6ln/credential'
I0226 00:48:28.444622 29949 slave.cpp:281] Slave using credential for: test-principal
I0226 00:48:28.444912 29949 slave.cpp:299] Slave resources: cpus(*):2; mem(*):1024; disk(*):454767; ports(*):[31000-32000]
I0226 00:48:28.445397 29949 slave.cpp:328] Slave hostname: smfd-atr-11-sr1.devel.twitter.com
I0226 00:48:28.445441 29949 slave.cpp:329] Slave checkpoint: false
W0226 00:48:28.445478 29949 slave.cpp:331] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I0226 00:48:28.445652 29967 process.cpp:2160] Resuming (267)@10.35.255.108:46621 at 2015-02-26 00:48:28.445640192+00:00
I0226 00:48:28.445734 29964 process.cpp:2160] Resuming __async_executor__(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.445725952+00:00
I0226 00:48:28.445725 29949 process.cpp:2150] Spawned process __async_executor__(13)@10.35.255.108:46621
I0226 00:48:28.445734 29948 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.445725952+00:00
I0226 00:48:28.445720 29960 process.cpp:2160] Resuming help@10.35.255.108:46621 at 2015-02-26 00:48:28.445700864+00:00
I0226 00:48:28.446018 29948 process.cpp:2160] Resuming __async_executor__(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.446012928+00:00
I0226 00:48:28.446058 29948 state.cpp:35] Recovering state from '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_GFm6ln/meta'
I0226 00:48:28.446117 29948 process.cpp:2267] Cleaning up __async_executor__(13)@10.35.255.108:46621
I0226 00:48:28.446112 29960 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.446106880+00:00
I0226 00:48:28.446215 29948 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.446213120+00:00
I0226 00:48:28.446302 29957 process.cpp:2160] Resuming (267)@10.35.255.108:46621 at 2015-02-26 00:48:28.446288128+00:00
I0226 00:48:28.446364 29957 status_update_manager.cpp:197] Recovering status update manager
I0226 00:48:28.446449 29969 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.446434048+00:00
I0226 00:48:28.446554 29931 process.cpp:2150] Spawned process standalone-master-detector(51)@10.35.255.108:46621
I0226 00:48:28.446576 29966 process.cpp:2160] Resuming standalone-master-detector(51)@10.35.255.108:46621 at 2015-02-26 00:48:28.446564864+00:00
I0226 00:48:28.446635 29969 slave.cpp:3775] Finished recovery
I0226 00:48:28.447001 29962 process.cpp:2160] Resuming standalone-master-detector(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.446994944+00:00
I0226 00:48:28.447109 29962 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.447074048+00:00
I0226 00:48:28.447181 29967 process.cpp:2160] Resuming (267)@10.35.255.108:46621 at 2015-02-26 00:48:28.447163136+00:00
I0226 00:48:28.447165 29962 pid.cpp:82] Attempting to parse 'master@10.35.255.108:46621' into a PID
I0226 00:48:28.447309 29967 status_update_manager.cpp:171] Pausing sending status updates
I0226 00:48:28.447335 29962 slave.cpp:624] New master detected at master@10.35.255.108:46621
I0226 00:48:28.447383 29962 slave.cpp:687] Authenticating with master master@10.35.255.108:46621
I0226 00:48:28.447409 29962 slave.cpp:692] Using default CRAM-MD5 authenticatee
I0226 00:48:28.447450 29962 process.cpp:2150] Spawned process crammd5_authenticatee(49)@10.35.255.108:46621
I0226 00:48:28.447490 29962 slave.cpp:660] Detecting new master
I0226 00:48:28.447510 29955 process.cpp:2160] Resuming crammd5_authenticatee(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.447457024+00:00
I0226 00:48:28.447535 29957 process.cpp:2160] Resuming standalone-master-detector(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.447525120+00:00
I0226 00:48:28.447618 29955 authenticatee.hpp:139] Creating new client SASL connection
I0226 00:48:28.447700 29955 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.447695872+00:00
I0226 00:48:28.447778 29955 pid.cpp:82] Attempting to parse 'slave(13)@10.35.255.108:46621' into a PID
I0226 00:48:28.447813 29955 master.cpp:3813] Authenticating slave(13)@10.35.255.108:46621
I0226 00:48:28.447854 29955 master.cpp:3824] Using default CRAM-MD5 authenticator
I0226 00:48:28.447896 29955 process.cpp:2150] Spawned process crammd5_authenticator(49)@10.35.255.108:46621
I0226 00:48:28.447914 29959 process.cpp:2160] Resuming crammd5_authenticator(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.447907072+00:00
I0226 00:48:28.448015 29959 authenticator.hpp:170] Creating new server SASL connection
I0226 00:48:28.448122 29959 process.cpp:2160] Resuming crammd5_authenticatee(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.448108032+00:00
I0226 00:48:28.448233 29959 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0226 00:48:28.448309 29959 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0226 00:48:28.448380 29952 process.cpp:2160] Resuming crammd5_authenticator(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.448371968+00:00
I0226 00:48:28.448456 29952 authenticator.hpp:276] Received SASL authentication start
I0226 00:48:28.448632 29952 authenticator.hpp:398] Authentication requires more steps
I0226 00:48:28.448683 29952 process.cpp:2160] Resuming crammd5_authenticatee(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.448678912+00:00
I0226 00:48:28.448750 29952 authenticatee.hpp:276] Received SASL authentication step
I0226 00:48:28.448817 29952 process.cpp:2160] Resuming metrics@10.35.255.108:46621 at 2015-02-26 00:48:28.448813056+00:00
I0226 00:48:28.448817 29931 sched.cpp:157] Version: 0.23.0
I0226 00:48:28.448884 29964 process.cpp:2160] Resuming crammd5_authenticator(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.448841984+00:00
I0226 00:48:28.448945 29952 process.cpp:2160] Resuming scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621 at 2015-02-26 00:48:28.448940032+00:00
I0226 00:48:28.448941 29931 process.cpp:2150] Spawned process scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621
I0226 00:48:28.449057 29964 authenticator.hpp:304] Received SASL authentication step
I0226 00:48:28.449101 29964 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'smfd-atr-11-sr1.devel.twitter.com' server FQDN: 'smfd-atr-11-sr1.devel.twitter.com' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0226 00:48:28.449115 29931 process.cpp:2150] Spawned process __latch__(259)@10.35.255.108:46621
I0226 00:48:28.449128 29969 process.cpp:2160] Resuming __latch__(259)@10.35.255.108:46621 at 2015-02-26 00:48:28.449118976+00:00
I0226 00:48:28.449173 29931 process.cpp:2150] Spawned process __waiter__(75)@10.35.255.108:46621
I0226 00:48:28.449131 29964 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0226 00:48:28.449100 29966 process.cpp:2160] Resuming standalone-master-detector(51)@10.35.255.108:46621 at 2015-02-26 00:48:28.449084928+00:00
I0226 00:48:28.449096 29954 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.449090048+00:00
I0226 00:48:28.449172 29953 process.cpp:2160] Resuming __waiter__(75)@10.35.255.108:46621 at 2015-02-26 00:48:28.449165056+00:00
I0226 00:48:28.449364 29966 process.cpp:2160] Resuming scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621 at 2015-02-26 00:48:28.449359872+00:00
I0226 00:48:28.449297 29964 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0226 00:48:28.449427 29966 pid.cpp:82] Attempting to parse 'master@10.35.255.108:46621' into a PID
I0226 00:48:28.449455 29964 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'smfd-atr-11-sr1.devel.twitter.com' server FQDN: 'smfd-atr-11-sr1.devel.twitter.com' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0226 00:48:28.449482 29966 sched.cpp:254] New master detected at master@10.35.255.108:46621
I0226 00:48:28.449502 29964 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0226 00:48:28.449532 29966 sched.cpp:310] Authenticating with master master@10.35.255.108:46621
I0226 00:48:28.449589 29966 sched.cpp:317] Using default CRAM-MD5 authenticatee
I0226 00:48:28.449565 29964 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0226 00:48:28.449635 29966 process.cpp:2150] Spawned process crammd5_authenticatee(50)@10.35.255.108:46621
I0226 00:48:28.449651 29963 process.cpp:2160] Resuming crammd5_authenticatee(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.449639936+00:00
I0226 00:48:28.449659 29964 authenticator.hpp:390] Authentication success
I0226 00:48:28.449694 29966 process.cpp:2160] Resuming standalone-master-detector(51)@10.35.255.108:46621 at 2015-02-26 00:48:28.449691136+00:00
I0226 00:48:28.449728 29963 authenticatee.hpp:139] Creating new client SASL connection
I0226 00:48:28.449756 29948 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.449750016+00:00
I0226 00:48:28.449739 29946 process.cpp:2160] Resuming crammd5_authenticatee(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.449733120+00:00
I0226 00:48:28.449823 29948 master.cpp:3871] Successfully authenticated principal 'test-principal' at slave(13)@10.35.255.108:46621
I0226 00:48:28.449852 29946 authenticatee.hpp:316] Authentication success
I0226 00:48:28.449883 29948 process.cpp:2465] Donating thread to crammd5_authenticator(49)@10.35.255.108:46621 while waiting
I0226 00:48:28.449915 29954 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.449908992+00:00
I0226 00:48:28.449918 29948 process.cpp:2160] Resuming crammd5_authenticator(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.449913088+00:00
I0226 00:48:28.449995 29948 process.cpp:2267] Cleaning up crammd5_authenticator(49)@10.35.255.108:46621
I0226 00:48:28.450036 29965 process.cpp:2160] Resuming crammd5_authenticatee(49)@10.35.255.108:46621 at 2015-02-26 00:48:28.450025984+00:00
I0226 00:48:28.450076 29948 pid.cpp:82] Attempting to parse 'scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621' into a PID
I0226 00:48:28.450099 29965 process.cpp:2267] Cleaning up crammd5_authenticatee(49)@10.35.255.108:46621
I0226 00:48:28.450124 29948 master.cpp:3813] Authenticating scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621
I0226 00:48:28.450176 29948 master.cpp:3824] Using default CRAM-MD5 authenticator
I0226 00:48:28.450175 29954 slave.cpp:758] Successfully authenticated with master master@10.35.255.108:46621
I0226 00:48:28.450218 29948 process.cpp:2150] Spawned process crammd5_authenticator(50)@10.35.255.108:46621
I0226 00:48:28.450229 29969 process.cpp:2160] Resuming crammd5_authenticator(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.450222848+00:00
I0226 00:48:28.450269 29954 slave.cpp:1090] Will retry registration in 12.70687ms if necessary
I0226 00:48:28.450317 29969 authenticator.hpp:170] Creating new server SASL connection
I0226 00:48:28.450325 29948 master.cpp:2938] Registering slave at slave(13)@10.35.255.108:46621 (smfd-atr-11-sr1.devel.twitter.com) with id 20150226-004828-1828659978-46621-29931-S0
I0226 00:48:28.450404 29955 process.cpp:2160] Resuming crammd5_authenticatee(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.450396928+00:00
I0226 00:48:28.450408 29946 process.cpp:2160] Resuming registrar(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.450401024+00:00
I0226 00:48:28.450477 29955 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0226 00:48:28.450522 29955 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0226 00:48:28.450542 29946 registrar.cpp:445] Applied 1 operations in 16646ns; attempting to update the 'registry'
I0226 00:48:28.450575 29955 process.cpp:2160] Resuming crammd5_authenticator(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.450571008+00:00
I0226 00:48:28.450636 29955 authenticator.hpp:276] Received SASL authentication start
I0226 00:48:28.450698 29955 authenticator.hpp:398] Authentication requires more steps
I0226 00:48:28.450795 29958 process.cpp:2160] Resuming crammd5_authenticatee(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.450742016+00:00
I0226 00:48:28.450857 29958 authenticatee.hpp:276] Received SASL authentication step
I0226 00:48:28.450911 29958 process.cpp:2160] Resuming crammd5_authenticator(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.450906880+00:00
I0226 00:48:28.450964 29958 authenticator.hpp:304] Received SASL authentication step
I0226 00:48:28.451005 29958 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'smfd-atr-11-sr1.devel.twitter.com' server FQDN: 'smfd-atr-11-sr1.devel.twitter.com' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0226 00:48:28.451031 29958 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0226 00:48:28.451055 29958 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0226 00:48:28.451079 29958 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'smfd-atr-11-sr1.devel.twitter.com' server FQDN: 'smfd-atr-11-sr1.devel.twitter.com' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0226 00:48:28.451104 29958 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0226 00:48:28.451130 29958 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0226 00:48:28.451165 29958 authenticator.hpp:390] Authentication success
I0226 00:48:28.451236 29958 process.cpp:2160] Resuming crammd5_authenticatee(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.451208192+00:00
I0226 00:48:28.451261 29969 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.451250176+00:00
I0226 00:48:28.451294 29958 authenticatee.hpp:316] Authentication success
I0226 00:48:28.451328 29969 master.cpp:3871] Successfully authenticated principal 'test-principal' at scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621
I0226 00:48:28.451382 29958 process.cpp:2160] Resuming scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621 at 2015-02-26 00:48:28.451358976+00:00
I0226 00:48:28.451411 29969 process.cpp:2465] Donating thread to crammd5_authenticator(50)@10.35.255.108:46621 while waiting
I0226 00:48:28.451442 29958 process.cpp:2465] Donating thread to crammd5_authenticatee(50)@10.35.255.108:46621 while waiting
I0226 00:48:28.451566 29969 process.cpp:2160] Resuming crammd5_authenticator(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.451563008+00:00
I0226 00:48:28.451601 29958 process.cpp:2160] Resuming crammd5_authenticatee(50)@10.35.255.108:46621 at 2015-02-26 00:48:28.451596032+00:00
I0226 00:48:28.451673 29958 process.cpp:2267] Cleaning up crammd5_authenticatee(50)@10.35.255.108:46621
I0226 00:48:28.451647 29969 process.cpp:2267] Cleaning up crammd5_authenticator(50)@10.35.255.108:46621
I0226 00:48:28.451724 29958 sched.cpp:398] Successfully authenticated with master master@10.35.255.108:46621
I0226 00:48:28.451776 29958 sched.cpp:521] Sending registration request to master@10.35.255.108:46621
I0226 00:48:28.451823 29958 sched.cpp:554] Will retry registration in 769.126565ms if necessary
I0226 00:48:28.451879 29964 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.451869952+00:00
I0226 00:48:28.451958 29964 master.cpp:1574] Received registration request for framework 'default' at scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621
I0226 00:48:28.452008 29964 master.cpp:1435] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0226 00:48:28.452055 29966 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.452048128+00:00
I0226 00:48:28.452075 29964 process.cpp:2160] Resuming authorizer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.452068096+00:00
I0226 00:48:28.452129 29947 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.452121088+00:00
I0226 00:48:28.452268 29960 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.452257024+00:00
I0226 00:48:28.452131 29955 process.cpp:2160] Resuming __latch__(260)@10.35.255.108:46621 at 2015-02-26 00:48:28.452124160+00:00
I0226 00:48:28.452121 29946 process.cpp:2150] Spawned process __latch__(260)@10.35.255.108:46621
I0226 00:48:28.452378 29956 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.452367104+00:00
I0226 00:48:28.452632 29956 log.cpp:684] Attempting to append 348 bytes to the log
I0226 00:48:28.452402 29960 master.cpp:1638] Registering framework 20150226-004828-1828659978-46621-29931-0000 (default) at scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621
I0226 00:48:28.452711 29956 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.452686080+00:00
I0226 00:48:28.452769 29956 coordinator.cpp:340] Coordinator attempting to write 2 action at position 3
I0226 00:48:28.452816 29956 process.cpp:2150] Spawned process log-write(114)@10.35.255.108:46621
I0226 00:48:28.452814 29960 process.cpp:2160] Resuming hierarchical-allocator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.452802816+00:00
I0226 00:48:28.452867 29948 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.452826112+00:00
I0226 00:48:28.453059 29960 hierarchical.hpp:321] Added framework 20150226-004828-1828659978-46621-29931-0000
I0226 00:48:28.452867 29969 process.cpp:2160] Resuming scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621 at 2015-02-26 00:48:28.452811008+00:00
I0226 00:48:28.452919 29952 process.cpp:2160] Resuming log-write(114)@10.35.255.108:46621 at 2015-02-26 00:48:28.452832000+00:00
I0226 00:48:28.452862 29967 process.cpp:2160] Resuming metrics@10.35.255.108:46621 at 2015-02-26 00:48:28.452805120+00:00
I0226 00:48:28.453166 29960 hierarchical.hpp:834] No resources available to allocate!
I0226 00:48:28.453232 29969 sched.cpp:448] Framework registered with 20150226-004828-1828659978-46621-29931-0000
I0226 00:48:28.453277 29952 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.453246208+00:00
I0226 00:48:28.453330 29969 sched.cpp:462] Scheduler::registered took 8465ns
I0226 00:48:28.453289 29960 hierarchical.hpp:741] Performed allocation for 0 slaves in 123147ns
I0226 00:48:28.453367 29969 process.cpp:2160] Resuming log-write(114)@10.35.255.108:46621 at 2015-02-26 00:48:28.453361920+00:00
I0226 00:48:28.453578 29952 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.453562112+00:00
I0226 00:48:28.453701 29952 process.cpp:2150] Spawned process (268)@10.35.255.108:46621
I0226 00:48:28.453763 29969 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.453756160+00:00
I0226 00:48:28.453801 29965 process.cpp:2160] Resuming (268)@10.35.255.108:46621 at 2015-02-26 00:48:28.453757952+00:00
I0226 00:48:28.453830 29955 process.cpp:2160] Resuming log-write(114)@10.35.255.108:46621 at 2015-02-26 00:48:28.453820928+00:00
I0226 00:48:28.454054 29952 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.454010880+00:00
I0226 00:48:28.454145 29952 replica.cpp:511] Replica received write request for position 3
I0226 00:48:28.460433 29952 leveldb.cpp:343] Persisting action (367 bytes) to leveldb took 6.237795ms
I0226 00:48:28.460484 29952 replica.cpp:679] Persisted action at 3
I0226 00:48:28.460536 29952 process.cpp:2160] Resuming (268)@10.35.255.108:46621 at 2015-02-26 00:48:28.460531968+00:00
I0226 00:48:28.460602 29952 process.cpp:2267] Cleaning up (268)@10.35.255.108:46621
I0226 00:48:28.460630 29965 process.cpp:2160] Resuming log-write(114)@10.35.255.108:46621 at 2015-02-26 00:48:28.460613888+00:00
I0226 00:48:28.460707 29952 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.460705024+00:00
I0226 00:48:28.460804 29962 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.460794880+00:00
I0226 00:48:28.460800 29965 process.cpp:2267] Cleaning up log-write(114)@10.35.255.108:46621
I0226 00:48:28.461027 29946 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.461019904+00:00
I0226 00:48:28.461032 29954 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.461021952+00:00
I0226 00:48:28.461390 29966 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.461321216+00:00
I0226 00:48:28.461390 29965 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.461321216+00:00
I0226 00:48:28.461520 29966 replica.cpp:658] Replica received learned notice for position 3
I0226 00:48:28.463649 29960 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.463636992+00:00
I0226 00:48:28.463773 29960 slave.cpp:1090] Will retry registration in 4.729454ms if necessary
I0226 00:48:28.463819 29946 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.463776000+00:00
I0226 00:48:28.463891 29946 master.cpp:2926] Ignoring register slave message from slave(13)@10.35.255.108:46621 (smfd-atr-11-sr1.devel.twitter.com) as admission is already in progress
I0226 00:48:28.468762 29966 leveldb.cpp:343] Persisting action (369 bytes) to leveldb took 7.194957ms
I0226 00:48:28.468817 29966 replica.cpp:679] Persisted action at 3
I0226 00:48:28.468848 29966 replica.cpp:664] Replica learned 2 action at position 3
I0226 00:48:28.468924 29950 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.468914944+00:00
I0226 00:48:28.469089 29966 process.cpp:2160] Resuming (258)@10.35.255.108:46621 at 2015-02-26 00:48:28.469082112+00:00
I0226 00:48:28.469205 29950 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.469198080+00:00
I0226 00:48:28.469257 29953 process.cpp:2160] Resuming __latch__(260)@10.35.255.108:46621 at 2015-02-26 00:48:28.469240064+00:00
I0226 00:48:28.469305 29959 process.cpp:2160] Resuming registrar(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.469274880+00:00
I0226 00:48:28.469352 29947 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.469327872+00:00
I0226 00:48:28.469343 29953 process.cpp:2267] Cleaning up __latch__(260)@10.35.255.108:46621
I0226 00:48:28.469358 29950 slave.cpp:1090] Will retry registration in 67.628014ms if necessary
I0226 00:48:28.469403 29959 registrar.cpp:490] Successfully updated the 'registry' in 18.816768ms
I0226 00:48:28.469434 29955 process.cpp:2160] Resuming log-writer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.469423104+00:00
I0226 00:48:28.469823 29955 log.cpp:703] Attempting to truncate the log to 3
I0226 00:48:28.469669 29953 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.469640960+00:00
I0226 00:48:28.469580 29947 master.cpp:2926] Ignoring register slave message from slave(13)@10.35.255.108:46621 (smfd-atr-11-sr1.devel.twitter.com) as admission is already in progress
I0226 00:48:28.470093 29960 process.cpp:2160] Resuming log-coordinator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.470074880+00:00
I0226 00:48:28.470326 29960 coordinator.cpp:340] Coordinator attempting to write 3 action at position 4
I0226 00:48:28.470226 29947 process.cpp:2150] Spawned process slave-observer(25)@10.35.255.108:46621
I0226 00:48:28.470435 29949 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.470424832+00:00
I0226 00:48:28.470413 29960 process.cpp:2150] Spawned process log-write(115)@10.35.255.108:46621
I0226 00:48:28.470439 29948 process.cpp:2160] Resuming log-write(115)@10.35.255.108:46621 at 2015-02-26 00:48:28.470432000+00:00
I0226 00:48:28.470713 29951 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.470686976+00:00
I0226 00:48:28.470578 29949 process.cpp:2160] Resuming hierarchical-allocator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.470573056+00:00
I0226 00:48:28.470825 29951 slave.cpp:792] Registered with master master@10.35.255.108:46621; given slave ID 20150226-004828-1828659978-46621-29931-S0
I0226 00:48:28.470922 29949 hierarchical.hpp:455] Added slave 20150226-004828-1828659978-46621-29931-S0 (smfd-atr-11-sr1.devel.twitter.com) with cpus(*):2; mem(*):1024; disk(*):454767; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):454767; ports(*):[31000-32000] available)
I0226 00:48:28.470679 29947 master.cpp:2995] Registered slave 20150226-004828-1828659978-46621-29931-S0 at slave(13)@10.35.255.108:46621 (smfd-atr-11-sr1.devel.twitter.com) with cpus(*):2; mem(*):1024; disk(*):454767; ports(*):[31000-32000]
I0226 00:48:28.471115 29949 hierarchical.hpp:814] Allocating cpus(*):2; mem(*):1024; disk(*):454767; ports(*):[31000-32000] on slave 20150226-004828-1828659978-46621-29931-S0 to framework 20150226-004828-1828659978-46621-29931-0000
I0226 00:48:28.470949 29952 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.470936064+00:00
I0226 00:48:28.470952 29948 process.cpp:2160] Resuming (267)@10.35.255.108:46621 at 2015-02-26 00:48:28.470936064+00:00
I0226 00:48:28.471261 29949 hierarchical.hpp:759] Performed allocation for slave 20150226-004828-1828659978-46621-29931-S0 in 220752ns
I0226 00:48:28.471273 29952 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.471268864+00:00
I0226 00:48:28.471285 29948 status_update_manager.cpp:178] Resuming sending status updates
I0226 00:48:28.471428 29952 master.cpp:3755] Sending 1 offers to framework 20150226-004828-1828659978-46621-29931-0000 (default) at scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621
I0226 00:48:28.470228 29946 process.cpp:2160] Resuming slave-observer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.470219008+00:00
I0226 00:48:28.471313 29953 process.cpp:2160] Resuming log-write(115)@10.35.255.108:46621 at 2015-02-26 00:48:28.471303936+00:00
I0226 00:48:28.471513 29949 process.cpp:2160] Resuming scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621 at 2015-02-26 00:48:28.471503872+00:00
I0226 00:48:28.471772 29959 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.471649024+00:00
I0226 00:48:28.471807 29953 process.cpp:2160] Resuming (257)@10.35.255.108:46621 at 2015-02-26 00:48:28.471771904+00:00
I0226 00:48:28.471861 29959 slave.cpp:2830] Received ping from slave-observer(25)@10.35.255.108:46621
I0226 00:48:28.471871 29949 sched.cpp:587] Received 1 offers
I0226 00:48:28.472038 29960 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.472024832+00:00
I0226 00:48:28.472076 29949 pid.cpp:82] Attempting to parse 'slave(13)@10.35.255.108:46621' into a PID
I0226 00:48:28.471987 29953 process.cpp:2150] Spawned process (269)@10.35.255.108:46621
I0226 00:48:28.472048 29950 process.cpp:2160] Resuming (269)@10.35.255.108:46621 at 2015-02-26 00:48:28.472039936+00:00
I0226 00:48:28.472411 29953 process.cpp:2160] Resuming log-write(115)@10.35.255.108:46621 at 2015-02-26 00:48:28.472360960+00:00
I0226 00:48:28.472055 29959 process.cpp:2160] Resuming slave-observer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.472052224+00:00
I0226 00:48:28.472463 29949 sched.cpp:611] Scheduler::resourceOffers took 215786ns
I0226 00:48:28.472463 29954 process.cpp:2160] Resuming log-replica(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.472455936+00:00
I0226 00:48:28.472790 29954 replica.cpp:511] Replica received write request for position 4
I0226 00:48:28.472795 29949 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.472785920+00:00
I0226 00:48:28.472978 29949 master.cpp:2268] Processing ACCEPT call for offers: [ 20150226-004828-1828659978-46621-29931-O0 ] on slave 20150226-004828-1828659978-46621-29931-S0 at slave(13)@10.35.255.108:46621 (smfd-atr-11-sr1.devel.twitter.com) for framework 20150226-004828-1828659978-46621-29931-0000 (default) at scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621
I0226 00:48:28.473026 29949 master.cpp:2112] Authorizing framework principal 'test-principal' to launch task 0 as user 'root'
I0226 00:48:28.473151 29949 process.cpp:2150] Spawned process (270)@10.35.255.108:46621
I0226 00:48:28.473151 29966 process.cpp:2160] Resuming authorizer(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.473126912+00:00
I0226 00:48:28.473170 29947 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.473161984+00:00
I0226 00:48:28.473176 29950 process.cpp:2160] Resuming (270)@10.35.255.108:46621 at 2015-02-26 00:48:28.473166848+00:00
I0226 00:48:28.473585 29950 process.cpp:2267] Cleaning up (270)@10.35.255.108:46621
I0226 00:48:28.473601 29963 process.cpp:2160] Resuming master@10.35.255.108:46621 at 2015-02-26 00:48:28.473423104+00:00
I0226 00:48:28.473681 29955 process.cpp:2160] Resuming __gc__@10.35.255.108:46621 at 2015-02-26 00:48:28.473673216+00:00
W0226 00:48:28.473789 29963 validation.cpp:326] Executor default for task 0 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0226 00:48:28.473832 29963 validation.cpp:338] Executor default for task 0 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0226 00:48:28.473901 29963 master.hpp:822] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 20150226-004828-1828659978-46621-29931-S0 (smfd-atr-11-sr1.devel.twitter.com)
I0226 00:48:28.473944 29963 master.cpp:2545] Launching task 0 of framework 20150226-004828-1828659978-46621-29931-0000 (default) at scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621 with resources cpus(*):1; mem(*):500 on slave 20150226-004828-1828659978-46621-29931-S0 at slave(13)@10.35.255.108:46621 (smfd-atr-11-sr1.devel.twitter.com)
I0226 00:48:28.474066 29963 process.cpp:2160] Resuming slave(13)@10.35.255.108:46621 at 2015-02-26 00:48:28.474062080+00:00
I0226 00:48:28.474103 29968 process.cpp:2160] Resuming hierarchical-allocator(25)@10.35.255.108:46621 at 2015-02-26 00:48:28.474072832+00:00
I0226 00:48:28.474138 29963 slave.cpp:1121] Got assigned task 0 for framework 20150226-004828-1828659978-46621-29931-0000
I0226 00:48:28.474313 29968 hierarchical.hpp:648] Recovered cpus(*):1; mem(*):524; disk(*):454767; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):524; disk(*):454767; ports(*):[31000-32000]) on slave 20150226-004828-1828659978-46621-29931-S0 from framework 20150226-004828-1828659978-46621-29931-0000
I0226 00:48:28.474375 29963 pid.cpp:82] Attempting to parse 'scheduler-1577dddb-e6a6-4994-8749-e27e0aeac4aa@10.35.255.108:46621' into a PID
I0226 00:48:28.474434 29968 hierarchical.hpp:684] Framework 20150226-004828-1828659978-46621-29931-0000 filtered slave 20150226-004828-1828659978-46621-29931-S0 for 5secs
I0226 00:48:28.474567 29963 slave.cpp:1231] Launching task 0 for framework 20150226-004828-1828659978-46621-29931-0000
I0226 00:48:28.476110 29963 slave.cpp:4177] Launching executor default of framework 20150226-004828-1828659978-46621-29931-0000 in work directory '/tmp/MasterAllocatorTest_0_FrameworkReregistersFirst_GFm6ln/slaves/20150226-004828-1828659978-46621-29931-S0/frameworks/20150226-004828-1828659978-46621-29931-0000/executors/default/runs/d0886d93-ef4b-4178-8b87-071689139c06'
*** Aborted at 1424911708 (unix time) try "date -d @1424911708" if you are using GNU date ***
PC: @     0x7f29a5ee581d __GI_getenv
*** SIGSEGV (@0xe0) received by PID 29931 (TID 0x7f299d699940) from PID 224; stack trace: ***
    @     0x7f29a7213ca0 (unknown)
    @     0x7f29a5ee581d __GI_getenv
    @     0x7f29a5f3f1a7 tzset_internal
    @     0x7f29a5f3fce0 __tzset
    @     0x7f29a5f449b4 __GI___strftime_l
    @     0x7f29a97c7fd8 process::operator<<()
    @     0x7f29a984ee35 process::ProcessManager::resume()
    @     0x7f29a984f2fc process::schedule()
    @     0x7f29a720b83d start_thread
    @     0x7f29a5f87fcd clone

Attachments

Issue Links

is broken by

MESOS-3475 TestContainerizer should not modify global environment variables.

Resolved

is related to

MESOS-2242 Make check segfault on CentOS5

Open

MESOS-1729 LogZooKeeperTest.WriteRead fails due to SIGPIPE (escalated to SIGABRT)

Resolved

relates to

MESOS-6216 LibeventSSLSocketImpl::create is not safe to call concurrently with os::getenv

Resolved

MESOS-8875 `leveldb::PosixEnv::DeleteFile()` can segfault.

Resolved

Activity

People

Assignee:: Unassigned

Reporter:: Vinod Kone

Votes:: 0 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 26/Feb/15 00:52

Updated:: 15/Jun/18 13:45

Resolved:: 15/Jun/18 13:45