Re: 'premature end of script headers' error

In message <[email protected]>,
Tom Ekberg writes:

>I tracked the problem down to an error in my detector. It was trying
>to write to a file in /tmp as apache but the file was owned by me.
>Removing the write in my detector fixed the problem.

Ah thanks for your work on this. Good job tracking this bug down.

>The exception that was generated was this:
>
>2013-12-13 11:41:16,918 DEBUG Caught exception <type 'exceptions.IOError'
>>: [Errno 13] Permission denied: '/tmp/nic.log'
>
>Note that this is an IOError exception. If you look at the HG source code
> in roundup/cgi/client.py you can find the inner_main method. Here is
> a skeleton of that method:
>
>     def inner_main(self):
>...
>         try:
>...
>             try:
>...
>                 html = self.handle_action()
>...
>             except IOError:
>                 # IOErrors here are due to the client disconnecting before
>                 # receiving the reply.
>                 pass
>...
>
>The detector got called about 7 levels down from handle_action(). Note
>that inner_main() ignores IOError exceptions. If something were written to
>the log in this except clause that would have saved me a lot of time. One
>of the first things I did was to turn on DEBUG logging. If I had seen the
>error in the log I would have been able to isolate the problem immediately.
>I suggest changing the above 'except IOError' clause to the following:
>
>             except IOError as e:
>                 # IOErrors here are due to the client disconnecting before
>                 # receiving the reply.
>                 # They can also be caused by detector errors.
>                 import traceback
>                 [...]
>                 lg.debug('Caught exception %s: %s\n%s' % (str(type(e)), ...
>
> However for this case, the roundup admin shouldn't be bothered with 
> client disconnect exceptions. I think logging it is the better approach.

I agree logging is a better alternative, but I really think that
logging should occur at warning or higher level.  Of course if we log
at that higher level, we need to worry about the impact on public
trackers under connect/disconnect attack. This would generate a lot of
logging for disconnect.

Is it possible to further refine how we handle that exception so we
can tell if the error was client disconnection (in which case we "pass")
or some other i/o error in which case it logs (at a warning level).

>I put the above IOError except clause code in my roundup/cgi/client.py
>(with the error put back in the detector) and got this in the log file:
>
>2013-12-13 13:39:36,690 DEBUG Caught exception <type 'exceptions.IOError'=
>>: [Errno 13] Permission denied: '/tmp/nic.log'
>Traceback (most recent call last):
>   File "/usr/local/lib/python2.7/site-packages/roundup/cgi/client.py", l=
>ine 479, in inner_main
>     html =3D self.handle_action()
>   File "/usr/local/lib/python2.7/site-packages/roundup/cgi/client.py", l=
>ine 1246, in handle_action
>     return action_klass(self).execute()
>   File "/usr/local/lib/python2.7/site-packages/roundup/cgi/actions.py", =
>line 40, in execute
>     return self.handle()
>   File "/usr/local/lib/python2.7/site-packages/roundup/cgi/actions.py", =
>line 630, in handle
>     message =3D self._editnodes(props, links)
>   File "/usr/local/lib/python2.7/site-packages/roundup/cgi/actions.py", =
>line 451, in _editnodes
>     props =3D self._changenode(cn, nodeid, props)
>   File "/usr/local/lib/python2.7/site-packages/roundup/cgi/actions.py", =
>line 513, in _changenode
>     ret =3D  cl.set(nodeid, **props)
>   File "/usr/local/lib/python2.7/site-packages/roundup/backends/rdbms_co=
>mmon.py", line 1723, in set
>     self.fireReactors('set', nodeid, oldvalues)
>   File "/usr/local/lib/python2.7/site-packages/roundup/hyperdb.py", line=
> 1263, in fireReactors
>     react(self.db, self, nodeid, oldvalues)
>   File "/var/www/html/systems/detectors/nic_collector.py", line 72, in c=
>ollector
>     write_log('setting %s to %s' % (nic_fields[nic_field], SEP + SEP.joi=
>n(new_values) + SEP))
>   File "/var/www/html/systems/detectors/nic_collector.py", line 41, in w=
>rite_log
>     logfile =3D open('/tmp/nic.log', 'a')
>IOError: [Errno 13] Permission denied: '/tmp/nic.log'

Do you have a traceback for the io error case when a client
disconnects? Is there something in the exception or the traceback we
can use to differentiate the disconnect case from any other case?

The other thing I am wondering is if this error might be better
handled by a error handler wrapping the call to:

   action_klass(self).execute

or in

   hyperdb.py:fireReactors()

(and equivalent for fireAuditors() or whever is the corresponding
function for auditors is called). I would prefer to fix the
inner_main() IOError handler since it can log other IOErrors that we
don't expect.

Also we should open an issue in the tracker with this email chain so it
gets fixed.

--
				-- rouilj
John Rouillard
===========================================================================
My employers don't acknowledge my existence much less my opinions.

------------------------------------------------------------------------------
Rapidly troubleshoot problems before they affect your business. Most IT 
organizations don't have a clear picture of how application performance 
affects their revenue. With AppDynamics, you get 100% visibility into your 
Java,.NET, & PHP application. Start your 15-day FREE TRIAL of AppDynamics Pro!
http://pubads.g.doubleclick.net/gampad/clk?id=84349831&iu=/4140/ostg.clktrk