[Buildbot-devel] lazy logs a bit too lazy and que'ed requests not being processed

Francesco Di Mizio francescodimizio at gmail.com
Thu Oct 23 13:41:25 UTC 2014


As a test I've sligthly changed the py script I am running to render its
output more readable:

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)


batch = 0
while True:

time.sleep(10)
print 'test bach %d\n' %batch
batch  += 1


I let the script go for a few seconds, then opened the log.
>From Wireshark, when I go "follow tcp stream" from the log request I get
(sorry for the wall of text) :

GET /builders/test_linux/builds/485/steps/shell/logs/stdio HTTP/1.1
Host: 192.168.15.174:8010
Connection: keep-alive
Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML,
like Gecko) Chrome/38.0.2125.104 Safari/537.36
Referer: http://192.168.15.174:8010/builders/test_linux/builds/485
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-US,en;q=0.8,it;q=0.6
Cookie: BuildBotSession=a12212813f540e2949c37e523ba45faa3027f6ac

HTTP/1.1 200 OK
Transfer-Encoding: chunked
Date: Thu, 23 Oct 2014 13:29:36 GMT
Cache-Control: no-cache
Content-Type: text/html; charset=utf-8
Server: TwistedWeb/13.2.0

a4f
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
    "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
  <html>
  <head><title>Log File contents</title>
  <link rel="stylesheet" href="../../../../../../../default.css"
type="text/css" />
  <script type="text/javascript">




    var active = true;
    window.onscroll = function() {




      var html = document.documentElement;
      active = (document.body.scrollTop + html.clientHeight >=
document.body.scrollHeight - 30);



    }
    window.setInterval(function() {




      if (active) {
        document.body.scrollTop = document.body.scrollHeight;




      }
    }, 300);




  </script>
  </head>
  <body class='log'>
    <a href="stdio/text">(view as text)</a><br/>
    <pre>
795
<span class="header">python /home/manage/loop_unbuffered.py
 in dir /var/lib/buildslave/test-slave/test_linux/build (timeout 1200 secs)
 watching logfiles {}
 argv: ['python', '/home/manage/loop_unbuffered.py']
 environment:
  HOME=/home/manage
  LANG=en_US.UTF-8
  LOGNAME=root

LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arj=01;31:*.taz=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lz=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.axa=00;36:*.oga=00;36:*.spx=00;36:*.xspf=00;36:
  MAIL=/var/mail/root
  PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
  PWD=/var/lib/buildslave/test-slave/test_linux/build
  SHELL=/bin/bash
  SUDO_COMMAND=/usr/bin/buildslave start test-slave
  SUDO_GID=1000
  SUDO_UID=1000
  SUDO_USER=manage
  TERM=xterm
  USER=root
  USERNAME=root
 using PTY: False
</span>
1ee
<span class="stdout">test bach 0

test bach 1

test bach 2

test bach 3

.... guess what? :)

test bach 32

test bach 33

</span>
2a
<span class="stdout">test bach 34

</span>
2a
<span class="stdout">test bach 35

</span>
2a
<span class="stdout">test bach 36

</span>


It keeps getting bigger and bigger. Still what I see if the browser saying
"waiting for 192.168.15.174"

Cheers,
 FDM

On Mon, Oct 20, 2014 at 9:57 PM, Dustin J. Mitchell <dustin at v.igoro.us>
wrote:

> Try *not* using Fiddler (it's just one more, unnecessary variable),
> and if it still doesn't work, try using Wireshark to capture traffic
> between your browser and Buildbot.
>
> Dustin
>
> On Mon, Oct 20, 2014 at 1:07 PM, Francesco Di Mizio
> <francescodimizio at gmail.com> wrote:
> > Some more info I got from Fiddler:
> >
> > SESSION STATE: ReadingResponse.
> > DOWNLOAD PROGRESS: 33,614 bytes.
> >
> >
> > == FLAGS ==================
> > BitFlags: [ClientPipeReused, ServerPipeReused] 0x18
> > X-CLIENTIP: 127.0.0.1
> > X-CLIENTPORT: 51030
> > X-EGRESSPORT: 51031
> > X-HOSTIP: 192.168.15.174
> > X-PROCESSINFO: chrome:10936
> > X-SERVERSOCKET: REUSE ServerPipe#3
> >
> > == TIMING INFO ============
> > ClientConnected: 18:53:10.904
> > ClientBeginRequest: 18:53:14.133
> > GotRequestHeaders: 18:53:14.133
> > ClientDoneRequest: 18:53:14.133
> > Determine Gateway: 0ms
> > DNS Lookup: 0ms
> > TCP/IP Connect: 0ms
> > HTTPS Handshake: 0ms
> > ServerConnected: 18:53:10.905
> > FiddlerBeginRequest: 18:53:14.133
> > ServerGotRequest: 18:53:14.133
> > ServerBeginResponse: 18:53:14.138
> > GotResponseHeaders: 18:53:14.138
> > ServerDoneResponse: 00:00:00.000
> > ClientBeginResponse: 00:00:00.000
> > ClientDoneResponse: 00:00:00.000
> >
> >
> > The response was buffered before delivery to the client.
> >
> > == WININET CACHE INFO ============
> > This URL is not present in the WinINET cache. [Code: 2]
> > * Note: Data above shows WinINET's current cache state, not the state at
> the
> > time of the request.
> > * Note: Data above shows WinINET's Medium Integrity (non-Protected Mode)
> > cache only.
> >
> >
> > DOWNLOAD PROGRESS keeps increasing during the step's execution. Just
> nothing
> > is being shown.
> > Also this sounds suspicious: The response was buffered before delivery to
> > the client.
> >
> >
> > On Mon, Oct 20, 2014 at 2:54 PM, Francesco Di Mizio
> > <francescodimizio at gmail.com> wrote:
> >>
> >> GET /builders/test_linux/builds/398/steps/shell/logs/stdio HTTP/1.1
> >> Host: 192.168.15.174:8010
> >> Accept:
> >>
> text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
> >> Accept-Encoding: gzip,deflate,sdch
> >> Accept-Language: en-US,en;q=0.8,it;q=0.6
> >> Cookie: BuildBotSession=4101a104fb9b505021468f7b7ee745e0bdf7adac
> >> Referer: http://192.168.15.174:8010/builders/test_linux/builds/398
> >> User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36
> (KHTML,
> >> like Gecko) Chrome/37.0.2062.124 Safari/537.36
> >>
> >> HTTP/1.1 200 OK
> >> Cache-Control: max-age=604800
> >> Content-Type: text/html; charset=utf-8
> >> Date: Mon, 20 Oct 2014 12:51:28 GMT
> >> Server: TwistedWeb/13.2.0
> >> Transfer-Encoding: chunked
> >>
> >> Once again, I can't see the response header until the step is over.
> >>
> >> Cheers,
> >>  FDM
> >>
> >>
> >> On Mon, Oct 20, 2014 at 2:10 PM, Benoît Allard
> >> <benoit.allard at greenbone.net> wrote:
> >>>
> >>> -----BEGIN PGP SIGNED MESSAGE-----
> >>> Hash: SHA1
> >>>
> >>> On 10/20/2014 11:53 AM, Francesco Di Mizio wrote:
> >>> > My production setup is indeed accessed via proxy (apache + mod
> >>> > proxy). Initially we all assumed that was the problem.
> >>> >
> >>> > After messing around with some proxy settings and seeing not light
> >>> > at the end of the tunnel, I tried a fresh install using a simple
> >>> > config with no proxy. It did not help.
> >>> >
> >>>
> >>> In my experience mod_proxy did not had the trouble nginx had by
> default.
> >>>
> >>> But there also exist transparent proxies ...
> >>>
> >>> Look at the HTTP headers of the pages served by buildbot (somewhere
> >>> inside your browser, depends on the browser), one of them should
> >>> indicate what's happening ...
> >>>
> >>> The technology used by buildbot there is called "Chunked transfer
> >>> encoding", and (as I said) is known to give some troubles with some
> >>> proxies that wait for the connection to be closed to 'proxy' it. If
> >>> you mention that to your network administrator, it might shed some
> >>> lights ...
> >>>
> >>> Good luck.
> >>>
> >>> - --
> >>> Benoît Allard (B30A05B0)|Greenbone Networks GmbH|http://greenbone.net
> >>> Neuer Graben 17, 49074 Osnabrück, Germany | AG Osnabrück, HR B 202460
> >>> Executive Directors: Lukas Grunwald, Dr. Jan-Oliver Wagner
> >>> -----BEGIN PGP SIGNATURE-----
> >>> Version: GnuPG v1.4.12 (GNU/Linux)
> >>>
> >>> iQEcBAEBAgAGBQJURPvGAAoJEHZCfVOzCgWwyaMH/0VEKFFM8tsdykUzxZbSPLzG
> >>> 54RFzL8//WVcMO4zflGdqGPmNAhuGIaHDz1+uVl9S+yvmDtL5xtZ3DOFDhyi1iAw
> >>> 8rW73OUQHJIokXtJwHJDf9JN960dSpR6E/L7KibNooc+TWEmUv0HIdmSDBpdSUdK
> >>> HmBa3VNlBHJ/43LfKn6YbbKkRfHEaLYB2BGp87GRiT/WqmMiSn/w8AGTKyyuog36
> >>> CHu0tWwqm2SR+xeU7wYt6YyYRxDD0jJaPgObHD0p2dsJ6FrGElMz9bs2+puydchG
> >>> GqfgdxiJwDmS6XKVCjutXAdW2LX5uYkfVKzbutF/Wp/b0VksV6fN9z6d+y5HlfQ=
> >>> =s7lZ
> >>> -----END PGP SIGNATURE-----
> >>
> >>
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://buildbot.net/pipermail/devel/attachments/20141023/67041760/attachment.html>


More information about the devel mailing list