Opened 8 years ago

Closed 7 years ago

#1897 closed enhancement (fixed)

b10-stats-httpd and HTTP logging

Reported by: jreed Owned by: jelte
Priority: medium Milestone: Sprint-20130205
Component: statistics Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 4 Add Hours to Ticket: 0
Total Hours: 0.5 Internal?: no

Description

b10-stats-httpd only uses logging framework for a little.

It uses the python http.server module for logging. This means it is not managed by the logging framework and just dumps to the stderr,

I suggest we use our logging framework and don't use http.server's methods for logging.

While here be sure to include a "S" in the logging identifier name; see ticket #1884.

Subtickets

Attachments (1)

http_log_message.patch (1.4 KB) - added by naokikambe 7 years ago.
proposed patch to use the logging framework

Download all attachments as: .zip

Change History (17)

comment:1 Changed 8 years ago by jreed

On a related note: It appears after some time the HTTP access logging for b10-stats-httpd stops logging. I saw a bunch of junk attempts in early April on two different servers (probably some attack attempt since were same). But nothing since then including my own use. I restarted bind10 and it began logging again. I should have just restarted only b10-stats-httpd for a test.

comment:2 Changed 8 years ago by jreed

On other system I only restarted b10-stats-httpd and the same bind10 restarted it and its same stderr output caught up with all HTTP logging since April 4th (almost two weeks ago) including all my attempts earlier today.

comment:3 Changed 8 years ago by naokikambe

I think we need to override the http.server.BaseHTTPRequestHandler.log_message method.

BTW the current log format seems to be based on "Common Log Format" which is a default log format of Apache. Should it continue to support this format? If yes, can our logging framework support this format?

localhost.localdomain - - [18/Apr/2012 17:14:27] "GET /bind10/statistics/xml HTTP/1.1" 200 -

comment:4 Changed 8 years ago by shane

  • Milestone New Tasks deleted
  • Type changed from defect to enhancement

Changed 7 years ago by naokikambe

proposed patch to use the logging framework

comment:5 Changed 7 years ago by jelte

  • Milestone set to Sprint-20130122

comment:6 follow-up: Changed 7 years ago by jelte

The patch looks ok in terms of how it works.

About the format, i think we have three reasonable options:

Currently it does 'bind10 style logs' which, as the log message, print CommonLog?-style data:

2013-01-11 12:20:42.112 DEBUG [b10-stats-httpd.stats-httpd/8646] STATHTTPD_HTTPLOG localhost - - [11/Jan/2013 12:20:42] "GET /bind10/statistics/xml/ HTTP/1.1" 200 -

So it is not exactly commonlog, and it contains redundant info (hardcoded '- -', datetime twice), but everything after the STATHTTPD_HTTPLOG is in the common style.

An alternative would be not doing that style at all, and print it in the bind10-style, e.g.:

2013-01-11 12:20:42.112 DEBUG [b10-stats-httpd.stats-httpd/8646] STATHTTPD_HTTPLOG localhost "GET /bind10/statistics/xml/ HTTP/1.1" 200

Advantage: internal consistency. Disadvantage: all resemblance to common log lost.

And the third would be to do it entirely in common log style, as the example above:

localhost.localdomain - - [18/Apr/2012 17:14:27] "GET /bind10/statistics/xml HTTP/1.1" 200 -

This option does require us to modify the logging library (to set layout) and our 'own' message would be kinda inconsistent though.

comment:7 in reply to: ↑ 6 Changed 7 years ago by naokikambe

I'm not sure how much we desire a complete CommonLog format for stats-httpd. So in a short term I think we should choose the first or second option. After that, if we receive many requests to a complete CommonLog format of stats-httpd, then we could move to the third option. For this approach, I think the second one would a bit better than the first one.

comment:8 Changed 7 years ago by jelte

  • Owner set to jelte
  • Status changed from new to assigned

comment:9 Changed 7 years ago by jelte

  • Owner changed from jelte to UnAssigned
  • Status changed from assigned to reviewing

OK this ticket seemed to have gotten stuck for a bit, so I took the proposed patch and modified it to the second option from the above list. It's in branch trac1897

comment:10 Changed 7 years ago by naokikambe

  • Owner changed from UnAssigned to naokikambe

Picking for review.

comment:11 Changed 7 years ago by naokikambe

  • Owner changed from naokikambe to jelte

The change looks okay for me. But my minor comments are:

  • This ticket is enhancement. Do we need an entry of ChangeLog for it?
  • We can probably test output of this log in lettuce. But I don't think it actually makes much sense. But if we do this, we would introduce a http client code in lettuce so that b10-stats-httpd is accessed via HTTP.

comment:12 Changed 7 years ago by jelte

  • Owner changed from jelte to naokikambe

Added a lettuce test (which only checks http status code, and log output, no response contents as of yet, but i guess we need to start somewhere).

Also, I only just noticed the last comment in the ticket description, so I also did a search&replace for STATHTTPD->STATSHTTPD (e.g. #1884)

As for a changelog, I agree we need one, but TBH I actually do consider this a defect; so my proposal is
[bug] kambe, jelte
b10-stats-httpd no longer dumps request information to the console, but uses the bind10 logging system. Additionally, the logging identifiers have been changed from STATHTTPD_* to STATSHTTPD_*

comment:13 Changed 7 years ago by naokikambe

  • Owner changed from naokikambe to jelte

Hello,

I had two errors in lettuce as following.

    And wait for bind10 stderr message STATHTTPD_STARTED                       # features/terrain/steps.py:34
    Traceback (most recent call last):
      File "/usr/local/lib/python2.6/site-packages/lettuce-0.2.9-py2.6.egg/lettuce/core.py", line 125, in __call__
        ret = self.function(self.step, *args, **kw)
      File "/home/kambe/git/tests/lettuce/features/terrain/steps.py", line 52, in wait_for_stderr_message
        (found, line) = world.processes.wait_for_stderr_str(process_name, strings, new, int(times))
      File "/home/kambe/git/tests/lettuce/features/terrain/terrain.py", line 351, in wait_for_stderr_str
        matches)
      File "/home/kambe/git/tests/lettuce/features/terrain/terrain.py", line 251, in wait_for_stderr_str
        strings, only_new, matches)
      File "/home/kambe/git/tests/lettuce/features/terrain/terrain.py", line 235, in _wait_for_output_str
        assert False, "Timeout waiting for process output: " + str(strings)
    AssertionError: Timeout waiting for process output: [u'STATHTTPD_STARTED']
    And wait for new bind10 stderr message localhost "GET / HTTP/1.0" 302 -                       # features/terrain/steps.py:34
    Traceback (most recent call last):
      File "/usr/local/lib/python2.6/site-packages/lettuce-0.2.9-py2.6.egg/lettuce/core.py", line 125, in __call__
        ret = self.function(self.step, *args, **kw)
      File "/home/kambe/git/tests/lettuce/features/terrain/steps.py", line 52, in wait_for_stderr_message
        (found, line) = world.processes.wait_for_stderr_str(process_name, strings, new, int(times))
      File "/home/kambe/git/tests/lettuce/features/terrain/terrain.py", line 351, in wait_for_stderr_str
        matches)
      File "/home/kambe/git/tests/lettuce/features/terrain/terrain.py", line 251, in wait_for_stderr_str
        strings, only_new, matches)
      File "/home/kambe/git/tests/lettuce/features/terrain/terrain.py", line 235, in _wait_for_output_str
        assert False, "Timeout waiting for process output: " + str(strings)
    AssertionError: Timeout waiting for process output: [u'localhost']

One is due to missing renaming the log identifier in features/bindctl_commands.feature. Please also rename STATHTTPD_ to STATSHTTPD_.

The other one is due to my machine name. My machine name happens to be r52.local which is resolved into 127.0.0.1 by /etc/hosts. So in my python, socket.getfqdn('127.0.0.1') indicates the machine name(r52.local) as following. socket.getfqdn() is used by http.server when logging.

Python 3.1.4 (default, Aug  7 2012, 13:32:23)
[GCC 4.2.1 20070831 patched [FreeBSD]] on freebsd9
Type "help", "copyright", "credits" or "license" for more information.
>>> import socket
>>> socket.getfqdn('127.0.0.1')
'r52.local'
>>>

The proposed change log entry looks okay for me. Thank you for adding me at the entry.
So please check the above codes and revise if needed. Thanks,

comment:14 follow-up: Changed 7 years ago by jelte

  • Owner changed from jelte to naokikambe

ok, updated test for new log ID and so that it does not check the hostname part; could you see if it passes now?

Thanks

comment:15 in reply to: ↑ 14 Changed 7 years ago by naokikambe

  • Owner changed from naokikambe to jelte
  • Total Hours changed from 0 to 0.5

Hello,

The changes look okay for me and the failed tests are passed. Please go merge.

Thanks,

comment:16 Changed 7 years ago by jelte

  • Resolution set to fixed
  • Status changed from reviewing to closed

thanks! merged, closing ticket.

Note: See TracTickets for help on using tickets.