RGW: Add more information to the "req done" log message#15263
RGW: Add more information to the "req done" log message#15263jharbott wants to merge 1 commit intoceph:masterfrom cloudbau:wip-rgw-logging
Conversation
|
@jrosenboom this info is a subset of what is in the ops log |
|
Yes, but for a high-volume site, we cannot afford to have more detailed logs, still we need this information in order to analyse slow requests or other issues. With about 1k requests/s, we already have a couple of GB of logs per day with only the minimal log levels active. |
mattbenjamin
left a comment
There was a problem hiding this comment.
can we avoid declaring extra temp vars?
src/rgw/rgw_process.cc
Outdated
|
|
||
| int http_ret = s->err.http_ret; | ||
| int op_ret = 0; | ||
| string op_name = "unknown"; |
There was a problem hiding this comment.
do we need to make this copy?
There was a problem hiding this comment.
Well, I guess one can setup some conditionals directly in the dout, but I'm not sure whether the added complexity will make up for added efficiency. The difficulty comes from the fact that this part of the code can also be reached via some error exits when things have gone wrong before, so I wanted to rather be on the safe side. Not sure whether the tests will handle all error situations so that one could be sure that there are no possibilities for core dumps introduced.
Feel free to propose an update, though.
src/rgw/rgw_process.cc
Outdated
| handler->put_op(op); | ||
| rest->put_handler(handler); | ||
|
|
||
| string user_id = "nobody"; |
There was a problem hiding this comment.
do we need to make this copy?
| ts = ceph_clock_now(); | ||
| } | ||
|
|
||
| utime_t RGWRequest::get_elapsed_time() { |
There was a problem hiding this comment.
Thanks @jrosenboom for bringing this, I'm interested about the get_elapsed_time part, it matches the meaning of s3 bucket logging log field `Turn-Around Time' (http://docs.aws.amazon.com/AmazonS3/latest/dev/LogFormat.html) . I'd like to log this field in the rgw ops log later.
Link to rgw: s3 bucket logging/server access logging #14841
src/rgw/rgw_process.cc
Outdated
|
|
||
| dout(1) << "====== req done req=" << hex << req << dec | ||
| << " op status=" << op_ret | ||
| << " op_name=" << op_name |
There was a problem hiding this comment.
Would prefer:
<< " op_name=" << (op ? op->name() : "unknown")
to take consistent with existing usage.
src/rgw/rgw_process.cc
Outdated
| dout(1) << "====== req done req=" << hex << req << dec | ||
| << " op status=" << op_ret | ||
| << " op_name=" << op_name | ||
| << " user_id=" << user_id |
There was a problem hiding this comment.
Would prefer:
<< " user_id=" << s->user->user_id
We should user_id assigned during authentication phrase.
There was a problem hiding this comment.
I think this can still be bad, if we reach this via some of the early error gotos. I added another conditional similar to the one above.
mikulely
left a comment
There was a problem hiding this comment.
@jrosenboom Please see my comment
src/rgw/rgw_process.cc
Outdated
| dout(1) << "====== req done req=" << hex << req << dec | ||
| << " op status=" << op_ret | ||
| << " op_name=" << (op ? op->name() : "unknown") | ||
| << " user_id=" << (s->user ? s->user->user_id.to_str() : "nobody") |
There was a problem hiding this comment.
Can we replace "nobody" with "" ? Because nobody is a valid uid, which can be created by user with radsgw-admin cmd.
As discussed in [1], add some further information when logging a finished request in rgw: - op_name - user_id - domain - request_uri - request_params - obj_size - duration With the duration being show here, we do not need the request start being logged, move it to a higher level. In the end it would be nice to aggregate all this information together with the additional data that civetweb is keeping, in particular remote_addr and num_bytes_sent, but this seems useful as a first step. [1] http://tracker.ceph.com/issues/19917 Signed-off-by: Jens Rosenboom <j.rosenboom@x-ion.de>
|
Updated with two more fields being output and a bit of amending the log levels. |
|
Jenkins re-test this please |
|
This pull request has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. |
|
Hi! So Was it implemented? I'm searching info how to add a duration of request to civetweb log |
As discussed in [1], add some further information when logging a finished
request in rgw:
In the end it would be nice to aggregate all this information together
with the additional data that civetweb is keeping, in particular
remote_addr and num_bytes_sent, but this seems useful as a first step.
[1] http://tracker.ceph.com/issues/19917
Signed-off-by: Jens Rosenboom j.rosenboom@x-ion.de