[Buildbot-devel] lazy logs a bit too lazy and que'ed requests not being processed
Dustin J. Mitchell
dustin at v.igoro.us
Wed Oct 15 17:34:18 UTC 2014
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
>> >>>> >>> >>>>
>> >>>> >>> >>>>
>> >>>> >>> >>>>
>> >>>> >>> >>>
>> >>>> >>> >>
>> >>>> >>> >
>> >>>> >>
>> >>>> >>
>> >>>> >
>> >>>
>> >>>
>> >>
>> >
>
>
More information about the devel
mailing list