[
https://issues.apache.org/jira/browse/MESOS-2407?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14339474#comment-14339474
]
Vinod Kone commented on MESOS-2407:
-----------------------------------
So there are 3 issues here.
1) thread safety of strftime() when setenv() is used. from grepping through the
code, we only ever do setenv() in tests (except of slave main and master main).
so this shouldn't be an issue in production. but we need to fix tests somehow.
2) thread safety of gmtime(). gmtime() is called in "operator << (std::ostream&
stream, const Time& time)" and HTTPResponse Encoder. we should use gmtime_r()
instead which is thread safe. i'll send a review for this.
3) thread safety of "<<" on OSX. not sure what we can do about this.
> 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)
