[Buildbot-devel] lazy logs a bit too lazy and que'ed requests not being processed
Francesco Di Mizio
francescodimizio at gmail.com
Wed Oct 15 17:02:54 UTC 2014
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/20141015/e616a348/attachment.html>
More information about the devel
mailing list