Added uuidv4 and now() in RFC3339 UTC Format by spagno · Pull Request #1645 · cherrypy/cherrypy

spagno · 2017-10-17T16:42:25Z

What kind of change does this PR introduce? (Bug fix, feature, docs update, ...)
feature
What is the related issue number (starting with #)
What is the current behavior? (You can also link to an open issue here)
There isn't the possibility to configure acces_log_format with uuidv4 and timestamp in rfc3339 format
What is the new behavior (if this is a feature change)?
You can use "%(i)s" to have a unique request_id in the log
You can use "%(z)s" to have a UTC rfc3339 timestamp in the log
Other information:
first PR ever, if something is wrong please don't be mean 🗡️

webknjaz · 2017-10-17T17:35:24Z

What did you try to do here? What went wrong? Do you need any assistance with this?

webknjaz · 2017-10-17T17:37:24Z

If you're concerned about broken linters, you just need to fix this:
https://travis-ci.org/cherrypy/cherrypy/jobs/289121270#L715

And then pushing new commit to the branch should fix that. You'll need to reopen this PR in such case.

spagno · 2017-10-17T17:59:53Z

thank you very much, I'm trying to understand why I broke that

spagno · 2017-10-17T18:24:52Z

Understood, I'll reopen the PR

codecov · 2017-10-17T18:25:01Z

Codecov Report

Merging #1645 into master will increase coverage by 0.57%.
The diff coverage is 89.28%.

@@            Coverage Diff             @@
##           master    #1645      +/-   ##
==========================================
+ Coverage   76.99%   77.57%   +0.57%     
==========================================
  Files         106      106              
  Lines       14313    14365      +52     
==========================================
+ Hits        11021    11143     +122     
+ Misses       3292     3222      -70

webknjaz · 2017-10-17T18:25:22Z

Oh, just follow the link and you'll see:

Fix double quoted strings................................................Failed
hookid: double-quote-string-fixer
Files were modified by this hook. Additional output:
Fixing strings in cherrypy/_cplogging.py

Which means that you used double quotes for strings, while the convention is to use single quotes.

You also can pip install pre-commit locally + do pre-commit run --all-files manually if needed :)

webknjaz · 2017-10-17T18:27:22Z

@spagno may I expect any tests for this additionally?

spagno · 2017-10-17T18:28:53Z

@webknjaz yes, I'm working on it. Just don't know if test all parameters (creating a new testing def) or just the new ones

webknjaz · 2017-10-17T18:32:36Z

@spagno both cases are fine.
I'd be thankful for testing just your changes, but if you're able to cover more — that would be fantastic :)

spagno · 2017-10-17T18:44:14Z

@webknjaz well I'll try!

spagno · 2017-10-18T02:09:04Z

seems like python in windows manages log differently from linux; can't run appropriate tests on windows, I have to delete the tests (for now) and reimplement them

webknjaz · 2017-10-18T07:13:41Z

+import uuid

 import cherrypy
+import six


Don't move it here, as it's a third-party. It must remain between stdlib imports and the project imports.

sorry, it was the visualstudio code import sorter, I'll not use it anymore

webknjaz · 2017-10-18T07:16:15Z

            exc_info = _cperror._exc_info()

-        self.error_log.log(severity, ' '.join((self.time(), context, msg)), exc_info=exc_info)
+        self.error_log.log(severity, ' '.join(


I think, it's nicer to split lines between arguments of log() method, not inside argument expressions.
Also please not that we follow 120-chars line restrictions (there's no 80-char terminals nowadays), so you don't really have to split it.

webknjaz · 2017-10-18T07:20:53Z

                 'f': dict.get(inheaders, 'Referer', ''),
                 'a': dict.get(inheaders, 'User-Agent', ''),
                 'o': dict.get(inheaders, 'Host', '-'),
+                 'i': str(uuid.uuid4()),


Why exactly do you need a new uuid for each access call shouldn't it be per-request?

because if you want to set different logformat with cherrypy._cplogging.LogManager.access_log_format(format)
if you want to have unique uuid for each request I thougth that could be the right place to set the uuid.
Use case:
I'm developing a simple semaphore dashboard for our CI; I want that the dashboard logs would be compliant with our best practices: in my case the configuration would be:
cherrypy._cplogging.LogManager.access_log_format('{"request_id":"%(i)s", "user-agent":"%(a)s", "timestamp": "%(z)s", "referrer":"%(f)s", "status":%(s)s, "remote_ip":"%(h)s"}')

I mean that it would call uuid.uuid4() every time access() is called if I remember correctly, meaning that there can be several different UUIDs generated per request if you'd call access() more then once. Right?

I've explored prior art and found out that @openstack uses %(uuid)s format string for this, so I'd like to follow the same convention.
Do you know any project using %(i)s for this?

Nope, uuid is generally custom (for example nginx) and in some cases it isn't supported and you have to do workaround for it (in haproxy you have to use a lua script for that). I decided to use "i" because there other atoms are single char, to mantain a sort of "convention"

(applies to both %(i)s and %(z)s)

Agree, for that reason I added only the atoms without touching the default access_log_format which is in standard Apache format

But they are still not lazy, meaning we waste CPU time calculating them.

got it, I'll fix it, thanks for the tips and sorry for the poor start quality: like I said it's my first public PR and I'm a sysadmin not a developer :D

No worries @spagno, I'm not judging. I'm here to help and walk you through the process :) You're doing great!

webknjaz · 2017-10-18T07:21:14Z

                 'a': dict.get(inheaders, 'User-Agent', ''),
                 'o': dict.get(inheaders, 'Host', '-'),
+                 'i': str(uuid.uuid4()),
+                 'z': self.time_z(),


What about exposing these atoms to error log?

you are right, I'll check how to do it

I read the code and I'm in a little in trouble: in the error_log the atoms aren't used at all, is that right? If it's right I think that adding this support could be out of scope of this PR and I can work on that with a different PR if there's the interest about that

well, supporting these atoms we allow users use them if they want to change that error_log format template. Okay, you can work on this separately.

webknjaz · 2017-10-18T07:21:50Z

 import time

 import six
-


no, there must be separation between stdlib and project imports

webknjaz · 2017-10-18T07:59:54Z

@spagno please don't remove tests w/o review as it's harder for me to find them in history and nearly impossible to comment in a nice way.

I've looked at the failed test and it turns out that your assertValidUUIDv4 helper has this data var:

data = [b'127.0.0.1 - - [18/Oct/2017:01:46:50] "GET /as_yield HTTP/1.1" 200 7 "" ""\r\n', b"b'test suite marker: '1508291210....RER" "USERAGENT" HOST\r\n', b"b'test suite marker: '1508291210.6715672\n", b'21afb35b-518c-4c20-a745-c6c071ba82c8\r\n']

And then at the first iteration of the loop you throw an error, while the UUID is the 3rd element.

If what I see in log is correct, you could improve it via smth like this:

...
data = [chunk.decode('utf-8').rstrip('\n').rstrip('\r') for chunk in data]
for log_chunk in data:
    try:
        uuid_log = data[-1]
        uuid_obj = UUID(uuid_log, version=4)
    except (TypeError, ValueError):
        msg = '%r not a valid UUIDv4' % uuid_log
        self._handleLogError(msg, data, marker, lines)
    else:
        if str(uuid_obj) != uuid_log:
            msg = '%r not a valid UUIDv4' % uuid_log
            self._handleLogError(msg, data, marker, lines)

webknjaz · 2017-10-18T14:37:53Z

        return ('[%02d/%s/%04d:%02d:%02d:%02d]' %
                (now.day, month, now.year, now.hour, now.minute, now.second))

+    def time_z(self):


@spagno plz turn this into @staticmethod

webknjaz · 2017-10-18T15:15:07Z

+import uuid

 import cherrypy
+


remove this line

webknjaz · 2017-10-18T15:15:21Z

 from cherrypy import _cperror
 from cherrypy._cpcompat import ntob

-


restore this line

webknjaz · 2017-10-18T15:17:08Z

 from cherrypy import _cperror
 from cherrypy._cpcompat import ntob

-


restore this line

webknjaz · 2017-10-20T11:41:51Z

@spagno I've pushed improvements and everything is likely to work well for now. Still, I'd like to better test time_z (maybe use spy object for that).

@spagno

PR #1645 by @spagno: * ``i`` holds a per-request UUID4 * ``z`` outputs UTC time in format of RFC 3339 * ``cherrypy._cprequest.Request.unique_id.uuid4`` now has lazily invocable UUID4

spagno closed this Oct 17, 2017

spagno reopened this Oct 17, 2017

webknjaz requested review from jaraco and webknjaz October 17, 2017 18:32

cherrypy deleted a comment Oct 18, 2017

webknjaz requested changes Oct 18, 2017

View reviewed changes

webknjaz reviewed Oct 18, 2017

View reviewed changes

spagno force-pushed the master branch 3 times, most recently from 1cc3046 to d60b61f Compare October 18, 2017 14:50

webknjaz reviewed Oct 18, 2017

View reviewed changes

Comment thread cherrypy/_cplogging.py Outdated

import uuid

import cherrypy

Copy link
Copy Markdown

Member

webknjaz Oct 18, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

remove this line

webknjaz reviewed Oct 18, 2017

View reviewed changes

spagno and others added 11 commits October 20, 2017 13:19

fixed unnecessary spaces

1a8fd6a

uuid lazy property

565c730

Trying new method

65656df

Added required blankline

cb9cd8f

Fixed uuidv4 generation

14a0af8

fixed request.uuid

7adbde1

fixed string

584d2fb

added get_uuid

256825b

Fixed double quoted strings

31991d5

Make time_z lazily evaluated for logging

2aea16e

Extend req w/ lazily evald on rend unique_id prop

6c508d6

webknjaz force-pushed the master branch from 61ac10d to 6c508d6 Compare October 20, 2017 10:19

webknjaz added 11 commits October 20, 2017 13:20

Drop bogus _cprequest.Response._uuid property

f27d41a

Restore accidentally removed line separation

c1876ce

Cleanup bogus tests

bb137b7

Add missing import to logtest helper

131e53a

Fix LazyUUID4 string rendering method

438c648

Fix UUID4 test

da05e7a

Use proper @mock.patch for log_format substitution

7e16a5a

Fix docstring in test to be PEP257-compliant

61e3356

Use mock.patch for all logging tests

3e0af3c

Improve UUID assertion in logging tests

7e41ee7

Add test for Request.unique_id per-req property

8b21372

webknjaz force-pushed the master branch from e49cc7e to 7a499f0 Compare October 20, 2017 11:19

Restore original access log custom format test

4743879

webknjaz force-pushed the master branch from 7a499f0 to 4743879 Compare October 20, 2017 11:22

Mock timez log test to be more precise

122a484

webknjaz merged commit 122a484 into cherrypy:master Oct 20, 2017

		from cherrypy import _cperror
		from cherrypy._cpcompat import ntob

Uh oh!

Conversation

spagno commented Oct 17, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

webknjaz commented Oct 17, 2017

Uh oh!

webknjaz commented Oct 17, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

spagno commented Oct 17, 2017

Uh oh!

spagno commented Oct 17, 2017

Uh oh!

codecov Bot commented Oct 17, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

webknjaz commented Oct 17, 2017

Uh oh!

webknjaz commented Oct 17, 2017

Uh oh!

spagno commented Oct 17, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

webknjaz commented Oct 17, 2017

Uh oh!

spagno commented Oct 17, 2017

Uh oh!

spagno commented Oct 18, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

webknjaz commented Oct 18, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

webknjaz commented Oct 20, 2017

Uh oh!

spagno commented Oct 17, 2017 •

edited

Loading

webknjaz commented Oct 17, 2017 •

edited

Loading

codecov Bot commented Oct 17, 2017 •

edited

Loading

spagno commented Oct 17, 2017 •

edited

Loading

webknjaz commented Oct 18, 2017 •

edited

Loading