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

Dustin J. Mitchell dustin at v.igoro.us
Fri Oct 24 01:20:10 UTC 2014


Well, I suspect this is some kind of an abuse of the chunked transfer
encoding, anyway -- an HTML document isn't well-defined until the
</html>, and we're relying on browsers to interpret and render an
incomplete (and thus undefined) HTML document.  It's worked for over
ten years, but things change.  It's odd that it still works for me and
not for you, though.

Anyway, the new (nine) web UI is a totally different technology, so I
guess the best I can say!

Dustin

On Thu, Oct 23, 2014 at 9:05 PM, Francesco Di Mizio
<francescodimizio at gmail.com> wrote:
> That's what I thought as well. A quick Google search showed only one chrome
> issue with chunks but it was many years ago.
>
> I've also tried Firefox and ie with same results. I'll try updating them
> tomorrow, I doubt it'll work though...
>
> On Oct 24, 2014 2:55 AM, "Dustin J. Mitchell" <dustin at v.igoro.us> wrote:
>>
>> Sounds like a browser problem, then.  The "a4f", "795", and "1ee" are
>> chunk headers, and the browser should be rendering those as it
>> receives them.
>>
>> That's kind of crazy.  It works fine for me in a recent Firefox.  I
>> haven't tried Chrome in a while.
>>
>> Dustin
>>
>> On Thu, Oct 23, 2014 at 9:41 AM, Francesco Di Mizio
>> <francescodimizio at gmail.com> wrote:
>> > 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-----
>> >> >>
>> >> >>
>> >> >
>> >
>> >




More information about the devel mailing list