D5749: hgweb: log error before attempting I/O

[mharbison72 (Matt Harbison)]

mharbison72 added a comment.


  In https://phab.mercurial-scm.org/D5749#84825, @durin42 wrote:
  
  > In https://phab.mercurial-scm.org/D5749#84719, @mharbison72 wrote:
  >
  > > In https://phab.mercurial-scm.org/D5749#84640, @indygreg wrote:
  > >
  > > > @durin42 and I were both able to produce intermittent failures with this change. Why, I'm not sure.
  > > >
  > > > Does the Windows regression occur with this patch or with https://phab.mercurial-scm.org/D5751? I ask because the behavior of `socket.shutdown()` is documented to vary by platform. I wouldn't at all be surprised if https://phab.mercurial-scm.org/D5751 caused the regression seen here.
  > >
  > >
  > > It was this patch.
  > >
  > > Like I said, I’ve seen connection resets in the non-daemonized serve output (don’t recall if it was push, pull, or both). I thought it was weird, but there were no other signs of problems, so I wrote it off as some odd Windows thing. (Not sure that I’ve seen it on Linux or OS X too)
  >
  >
  > Does https://phab.mercurial-scm.org/D5764 help the situation? It made a big difference for me.
  
  
  That helps a lot.  I was able to run this ~200 times in --loop without issue (with py3).  Then I got a few flyers:
  
    --- d:/mercurial/tests/test-hgweb-filelog.t
    +++ d:/mercurial/tests/test-hgweb-filelog.t.err
    @@ -1843,5 +1843,19 @@
     errors
    
       $ cat errors.log
    +  $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/log/3/a?linerange=1:a':
    +  Traceback (most recent call last):
    +    File "d:\mercurial\mercurial\hgweb\server.py", line 102, in do_POST
    +      self.do_write()
    +    File "d:\mercurial\mercurial\hgweb\server.py", line 95, in do_write
    +      self.do_hgweb()
    +    File "d:\mercurial\mercurial\hgweb\server.py", line 204, in do_hgweb
    +      self._write(chunk)
    +    File "d:\mercurial\mercurial\hgweb\server.py", line 255, in _write
    +      self.wfile.write(data)
    +    File "C:\Program Files\Python37\Lib\socketserver.py", line 796, in write
    +      self._sock.sendall(b)
    +  ConnectionAbortedError: [WinError 10053] An established connection was aborted by the software in your host machine
    +
    
       $ cd ..
    
    ERROR: test-hgweb-filelog.t output changed
    !..................
    --- d:/mercurial/tests/test-hgweb.t
    +++ d:/mercurial/tests/test-hgweb.t.err
    @@ -911,6 +911,10 @@
     errors
    
       $ cat errors.log | "$PYTHON" $TESTDIR/filtertraceback.py
    +  $LOCALIP - - [$ERRDATE$] Exception happened during processing request '/spam':\r (esc)
    +  Traceback (most recent call last):\r (esc)
    +  ConnectionAbortedError: [WinError 10053] An established connection was aborted by the software in your host machine\r (esc)
    +  \r (esc)
       $ rm -f errors.log
    
     Uncaught exceptions result in a logged error and canned HTTP response
    
    ERROR: test-hgweb.t output changed
  
  So there might be a small race here, but I'm not concerned, given how rare it is.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D5749

To: indygreg, #hg-reviewers
Cc: durin42, mharbison72, mercurial-devel