[Buildbot-devel] lazy logs a bit too lazy and que'ed requests not being processed
Francesco Di Mizio
francescodimizio at gmail.com
Thu Oct 16 09:45:54 UTC 2014
Nop, it happens on Mac ans Linux too, at least on production.
Given the results I got from my test env, i doubt they'll work there
either. Still worth a try though.
On Wed, Oct 15, 2014 at 7:34 PM, Dustin J. Mitchell <dustin at v.igoro.us>
wrote:
> Well, unbuffering sys.stdout is needed if you kill the process, which
> makes sense: the buffer's still in memory when you kill the process.
>
> Does this only occur on Windows slaves?
>
> Dustin
>
> On Wed, Oct 15, 2014 at 1:02 PM, Francesco Di Mizio
> <francescodimizio at gmail.com> wrote:
> > Ok this is seriously driving me nuts. I did the following.
> >
> > Entirely new setup (0.8.9) on a new virtual machine (Ubuntu 10.04 server
> > x64) with a new IP.
> > Only one single windows slave on 0.8.9 as well.
> >
> > At this point I made sure I was able to succes. run the pyflakes config
> > which comes with buildbot. All right so far. Then I:
> >
> > - added a new Periodic scheduler which spits out a request every few
> > seonds.
> > - added a builder (kicked off by the Periodic scheduler) with only two
> > steps:
> >
> > testFactory.addStep(ShellCommand(command=['python',
> "c:\\loop_default.py"]))
> > testFactory.addStep(ShellCommand(command=['python',
> > "c:\\loop_unbuffered.py"]))
> >
> > loop_default.py looks like:
> >
> > import os
> > import time
> >
> > while True:
> > time.sleep(2)
> > print 'test'
> >
> > The result is: no streamed stdio and EMPTY stdio after the step is over.
> >
> > loop_unbuffered.py looks like:
> >
> > import os
> > import time
> > import sys
> >
> > class Unbuffered(object):
> > def __init__(self, stream):
> > self.stream = stream
> > def write(self, data):
> > self.stream.write(data)
> > self.stream.flush()
> > def __getattr__(self, attr):
> > return getattr(self.stream, attr)
> >
> >
> > sys.stdout = Unbuffered(sys.stdout)
> >
> > while True:
> > time.sleep(2)
> > print 'test'
> >
> > The result is: no streamed stdio but at least populated stdio after the
> step
> > is over.
> >
> > Note that above are two infinite loops. To terminate them I was manually
> > killing them on the slave. Which explains why I didnt get stdout with the
> > loop_standard version. It never quit smoothly so no flush. I managed to
> > confirm this even by running the two py scripts locally and redirecting
> > stdout as Dustin had suggested. In the case of Ioop_default.py, I can't
> see
> > any output until I kill it.
> >
> > I then did the same test, same scripts with the only addition of
> quitting(0)
> > after printing 10 lines.
> >
> > Result was (now expected, as Ioop_default.py can now quit gracefully) the
> > same for either steps:
> >
> > no streamed stdio but at least populated stdio after the step is over.
> >
> >
> > Conclusion so far: unbuffering sys.stout is needed. Why do logs keep not
> > streaming? No idea.
> >
> > Cheers,
> > Francesco
> >
> >
> > On Tue, Oct 14, 2014 at 6:08 PM, Dustin J. Mitchell <dustin at v.igoro.us>
> > wrote:
> >>
> >> Well, but this works for just about everyone else, so there's
> >> something unique about your configuration. All I can suggest is to
> >> try to figure out what that unique thing is. Perhaps you can start by
> >> minimizing the example. It might make sense to just start with a
> >> basic configuration (not one derived from your production
> >> configuration). If you're still seeing the no-streamed-logs behavior
> >> with that configuration, then you've learned something about where the
> >> error is and is not.
> >>
> >> Dustin
> >>
> >> On Tue, Oct 14, 2014 at 10:34 AM, Francesco Di Mizio
> >> <francescodimizio at gmail.com> wrote:
> >> > Got it to work, still no logs. Exactly the same as for 0.8.6 with no
> >> > proxy
> >> > again.
> >> >
> >> > On Tue, Oct 14, 2014 at 2:46 PM, Francesco Di Mizio
> >> > <francescodimizio at gmail.com> wrote:
> >> >>
> >> >> So started again form scratch, buildbot 0.8.9 on both slave and
> server.
> >> >> After replacing a few things due to them being deprecated... the
> master
> >> >> starts fine.
> >> >>
> >> >> I didn't even get to see the logs as requests are pending but don't
> get
> >> >> picked up. Of course slaves are available.
> >> >>
> >> >> Cheers,
> >> >> Francesco
> >> >>
> >> >> On Tue, Oct 14, 2014 at 10:54 AM, Francesco Di Mizio
> >> >> <francescodimizio at gmail.com> wrote:
> >> >>>
> >> >>> Yep it seems we have a slightly modified version of the code. In
> >> >>> particular the _start method of RemoteCommand:
> >> >>>
> >> >>> def _start(self):
> >> >>> if 'stdio' not in self.logs or 'stdio' not in
> >> >>> self.delayedLogs:
> >> >>> log.msg("RemoteCommand (%s) is running a command, but "
> >> >>> "it isn't being logged to anything. This seems
> >> >>> unusual."
> >> >>> % self)
> >> >>> self.updates = {}
> >> >>> self._startTime = util.now()
> >> >>>
> >> >>> # This method only initiates the remote command.
> >> >>> # We will receive remote_update messages as the command
> runs.
> >> >>> # We will get a single remote_complete when it finishes.
> >> >>> # We should fire self.deferred when the command is done.
> >> >>> d = self.remote.callRemote("startCommand", self,
> >> >>> self.commandID,
> >> >>> self.remote_command, self.args)
> >> >>> return d
> >> >>>
> >> >>> with the stuff in red being the added part.
> >> >>>
> >> >>> I really could not figure it out as we have that source checked in
> in
> >> >>> our
> >> >>> version control. And the the first revision already contains that
> >> >>> change.
> >> >>> I'll download 0.8.6 again and start with a fresh install.
> >> >>>
> >> >>> Chers,
> >> >>> Francesco
> >> >>>
> >> >>>
> >> >>> On Tue, Oct 14, 2014 at 2:05 AM, Dustin J. Mitchell
> >> >>> <dustin at v.igoro.us>
> >> >>> wrote:
> >> >>>>
> >> >>>>
> >> >>>>
> >> >>>>
> https://github.com/buildbot/buildbot/blob/eight/master/buildbot/status/web/logs.py
> >> >>>> is where the streaming takes place.
> >> >>>>
> >> >>>> As for "is running a command, but it isn't being logged to
> anything.
> >> >>>> This seems unusual.", I don't see that message anywhere in the
> >> >>>> Buildbot codebase. Presumably it's some custom code of yours?
> >> >>>>
> >> >>>> Dustin
> >> >>>>
> >> >>>> On Mon, Oct 13, 2014 at 12:56 PM, Francesco Di Mizio
> >> >>>> <francescodimizio at gmail.com> wrote:
> >> >>>> > Sorry to bother you again. I've tried to set up a new instance of
> >> >>>> > buildbot
> >> >>>> > just for testing, which is being served without a proxy.
> >> >>>> >
> >> >>>> > Well logs streaming is not working yet... from the logs I gather:
> >> >>>> >
> >> >>>> > <RemoteShellCommand... is running a command, but it isn't being
> >> >>>> > logged
> >> >>>> > to
> >> >>>> > anything. This seems unusual.
> >> >>>> >
> >> >>>> > On Mon, Oct 13, 2014 at 11:50 AM, Francesco Di Mizio
> >> >>>> > <francescodimizio at gmail.com> wrote:
> >> >>>> >>
> >> >>>> >> Yep you are right I'll see their mailing list.
> >> >>>> >>
> >> >>>> >> One very last thing: Should I need to provide them with more
> >> >>>> >> details,
> >> >>>> >> could you please point me to the relevant code for streaming
> logs?
> >> >>>> >>
> >> >>>> >> FDM
> >> >>>> >>
> >> >>>> >> On Sat, Oct 11, 2014 at 5:36 AM, Dustin J. Mitchell
> >> >>>> >> <dustin at v.igoro.us>
> >> >>>> >> wrote:
> >> >>>> >>>
> >> >>>> >>> At this point it's an Apache question, so you might have better
> >> >>>> >>> luck
> >> >>>> >>> seeking out Apache experts (of which I, at least, am not one).
> >> >>>> >>>
> >> >>>> >>> Dustin
> >> >>>> >>>
> >> >>>> >>> On Fri, Oct 10, 2014 at 6:57 AM, Francesco Di Mizio
> >> >>>> >>> <francescodimizio at gmail.com> wrote:
> >> >>>> >>> > No sure of this can be of any help:
> >> >>>> >>> >
> >> >>>> >>> > apache's error.log:
> >> >>>> >>> >
> >> >>>> >>> > [Fri Oct 10 12:54:17 2014] [debug] proxy_util.c(1818): proxy:
> >> >>>> >>> > grabbed
> >> >>>> >>> > scoreboard slot 1 in child 7231 for worker proxy:reverse
> >> >>>> >>> > [Fri Oct 10 12:54:17 2014] [debug] proxy_util.c(1837): proxy:
> >> >>>> >>> > worker
> >> >>>> >>> > proxy:reverse already initialized
> >> >>>> >>> > [Fri Oct 10 12:54:17 2014] [debug] proxy_util.c(1934): proxy:
> >> >>>> >>> > initialized
> >> >>>> >>> > single connection worker 1 in child 7231 for (*)
> >> >>>> >>> >
> >> >>>> >>> >
> >> >>>> >>> > On Thu, Oct 9, 2014 at 11:03 AM, Francesco Di Mizio
> >> >>>> >>> > <francescodimizio at gmail.com> wrote:
> >> >>>> >>> >>
> >> >>>> >>> >> I can't seem to find a solution for this, I'll give up for
> >> >>>> >>> >> now.
> >> >>>> >>> >> Really
> >> >>>> >>> >> ran
> >> >>>> >>> >> out of ideas.
> >> >>>> >>> >>
> >> >>>> >>> >> Initially in my email I mentioned one more issue other than
> >> >>>> >>> >> the
> >> >>>> >>> >> one
> >> >>>> >>> >> we've
> >> >>>> >>> >> been discussing.
> >> >>>> >>> >>
> >> >>>> >>> >> I'll just start a new thread not to mess this thread up.
> >> >>>> >>> >>
> >> >>>> >>> >> Cheers
> >> >>>> >>> >>
> >> >>>> >>> >> On Wed, Oct 8, 2014 at 4:25 PM, Francesco Di Mizio
> >> >>>> >>> >> <francescodimizio at gmail.com> wrote:
> >> >>>> >>> >>>
> >> >>>> >>> >>> Well according to the docs I don't see how dropping that to
> >> >>>> >>> >>> 512
> >> >>>> >>> >>> could
> >> >>>> >>> >>> have any effect as based on the docs:
> >> >>>> >>> >>>
> >> >>>> >>> >>> The size must be at least 8192.
> >> >>>> >>> >>>
> >> >>>> >>> >>> I gave it a try anyway with no visible results.
> >> >>>> >>> >>>
> >> >>>> >>> >>> Forget about lazy logs in the buildbot sense of the term, I
> >> >>>> >>> >>> am
> >> >>>> >>> >>> not
> >> >>>> >>> >>> using
> >> >>>> >>> >>> them either.
> >> >>>> >>> >>>
> >> >>>> >>> >>> Thanks for your help :)
> >> >>>> >>> >>>
> >> >>>> >>> >>> On Wed, Oct 8, 2014 at 3:55 PM, Charles Lepple
> >> >>>> >>> >>> <clepple at gmail.com>
> >> >>>> >>> >>> wrote:
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> On Oct 8, 2014, at 9:46 AM, Francesco Di Mizio
> >> >>>> >>> >>>> <francescodimizio at gmail.com> wrote:
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> In a previous reply, Charles wrote:
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> In Apache, I dropped the proxy buffer from the default of
> 8
> >> >>>> >>> >>>> kB
> >> >>>> >>> >>>> to
> >> >>>> >>> >>>> 512
> >> >>>> >>> >>>> byte.
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> I am assuming you are talking about the
> >> >>>> >>> >>>> ProxyReceiveBufferSize.
> >> >>>> >>> >>>> Am I
> >> >>>> >>> >>>> assuming right?
> >> >>>> >>> >>>>
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> actually, it was ProxyIOBufferSize, which also defaults to
> >> >>>> >>> >>>> 8kB:
> >> >>>> >>> >>>>
> >> >>>> >>> >>>>
> >> >>>> >>> >>>>
> >> >>>> >>> >>>>
> >> >>>> >>> >>>>
> http://httpd.apache.org/docs/2.2/mod/mod_proxy.html#proxyiobuffersize
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> I don't remember why I adjusted that one versus the
> receive
> >> >>>> >>> >>>> buffer.
> >> >>>> >>> >>>> This
> >> >>>> >>> >>>> is with Apache 2.2.
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> Also, I am not using "lazy logs" - I didn't realize that
> was
> >> >>>> >>> >>>> a
> >> >>>> >>> >>>> specific
> >> >>>> >>> >>>> term. I was just trying to follow normal stdio logs with
> >> >>>> >>> >>>> less
> >> >>>> >>> >>>> delay.
> >> >>>> >>> >>>>
> >> >>>> >>> >>>> --
> >> >>>> >>> >>>> Charles Lepple
> >> >>>> >>> >>>> clepple at gmail
> >> >>>> >>> >>>>
> >> >>>> >>> >>>>
> >> >>>> >>> >>>>
> >> >>>> >>> >>>
> >> >>>> >>> >>
> >> >>>> >>> >
> >> >>>> >>
> >> >>>> >>
> >> >>>> >
> >> >>>
> >> >>>
> >> >>
> >> >
> >
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://buildbot.net/pipermail/devel/attachments/20141016/47afe153/attachment.html>
More information about the devel
mailing list