[
https://issues.apache.org/jira/browse/MESOS-2407?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14339001#comment-14339001
]
James DeFelice commented on MESOS-2407:
---------------------------------------
gmtime isn't thread-safe either. should use gmtime_r
(http://linux.die.net/man/3/gmtime_r).
Other projects have had the same problem, e.g.
http://sourceforge.net/p/levent/bugs/_discuss/thread/465dad36/948e/attachment/0001-Avoid-use-of-non-threadsafe-locale-dependent-strftim.patch
> libprocess segfaults when using GLOG_v=2
> ----------------------------------------
>
> Key: MESOS-2407
> URL: https://issues.apache.org/jira/browse/MESOS-2407
> Project: Mesos
> Issue Type: Bug
> Reporter: Vinod Kone
> Priority: Blocker
>
> Found this while debugging MESOS-2403. Looks like a thread safety issue with
> stream operator in Process::resume().
> {code}
> [==========] 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
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
