Project

General

Profile

Bug #16854

the usage log record date is 16 hours later than the real operate time in jewel1 10.2.2 rgw

Added by joke lee over 6 years ago. Updated about 6 years ago.

Status:
In Progress
Priority:
Low
Assignee:
Target version:
-
% Done:

0%

Source:
other
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

hi all,
i want get the usage of user,so i use the command radosgw-admin usage
show ,but i can not get the usage when i use the --start-date unless minus
16 hours

i have rgw both on ceph01 and ceph03,civeweb:7480 port ,and the ceph
version is jewel 10.2.2

the time zone of ceph01 and ceph03
[root at ceph03 ~]# ls -l /etc/localtime
lrwxrwxrwx 1 root root 35 Jul 25 07:40 /etc/localtime ->
../usr/share/zoneinfo/Asia/Shanghai
[root at ceph03 ~]# ssh ceph01 ls -l /etc/localtime
lrwxrwxrwx 1 root root 35 Jul 25 14:14 /etc/localtime ->
../usr/share/zoneinfo/Asia/Shanghai

the timedateclt of ceph03

[root at ceph03 ~]# timedatectl
Warning: Ignoring the TZ variable. Reading the system's time zone setting
only.

Local time: Fri 2016-07-29 08:28:44 CST
Universal time: Fri 2016-07-29 00:28:44 UTC
RTC time: Fri 2016-07-29 00:28:44
Time zone: Asia/Shanghai (CST, +0800)
NTP enabled: yes
NTP synchronized: yes
RTC in local TZ: no
DST active: n/a

the timedate of ceph01
[root at ceph03 ~]# ssh ceph01 timedatectl
Local time: Fri 2016-07-29 08:32:43 CST
Universal time: Fri 2016-07-29 00:32:43 UTC
RTC time: Fri 2016-07-29 08:32:43
Time zone: Asia/Shanghai (CST, +0800)
NTP enabled: yes
NTP synchronized: yes
RTC in local TZ: no
DST active: n/a

i create bucket use the python script test2.py

[root at ceph01 ~]# cat test2.py
import requests
import logging
from datetime import *
from requests_toolbelt.utils import dump
from awsauth import S3Auth
  1. host = 'yuliyangdebugwebjewel.tunnel.qydev.com'
    #host = 'yuliyangdebugweb68.tunnel.qydev.com'
    #host = '10.254.9.20:7480'
    host = '10.254.3.68:7480' #ceph03
    #host = '127.0.0.1:7480' #ceph01
    logging.basicConfig(level=logging.DEBUG)
    access_key = 'date2'
    secret_key = 'date2'
    cmd = '/%s' % '{:%m_%d.%H_%M_%S}'.format(datetime.now())
    #cmd = '/%s' % '{:%m_%d.%H_%M_%S}'.format(datetime.now() -
    timedelta(hours=16))
    url = 'http://%s%s' % (host,cmd)
    response = requests.put(url,auth=S3Auth(access_key,
    secret_key,service_url=host))

data = dump.dump_all(response)
print(data.decode('utf-8'))

and it's output

INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection
(1): 10.254.3.68
DEBUG:requests.packages.urllib3.connectionpool:"PUT /07_29.08_34_42
HTTP/1.1" 200 0
< PUT /07_29.08_34_42 HTTP/1.1
< Host: 10.254.3.68:7480
< Content-Length: 0
< Accept-Encoding: gzip, deflate
< Accept: */*
< User-Agent: python-requests/2.6.0 CPython/2.7.5
Linux/3.10.0-327.el7.x86_64
< Connection: keep-alive
< date: Fri, 29 Jul 2016 00:34:42 GMT
< Authorization: AWS date2:F+KLuenLNP42e25P/My/VWoUkeA=
<

HTTP/1.1 200 OK
date: Fri, 29 Jul 2016 00:34:42 GMT
content-length: 0
x-amz-request-id: tx000000000000000016112-00579aa4a2-c4c4f-default
connection: Keep-Alive

but the usage show the bucket create 16 hours before

[root at ceph01 ~]# radosgw-admin usage show --uid=date2 |grep 07_29.08_34_42
-A30
"bucket": "07_29.08_34_42",
"time": "2016-07-28 16:00:00.000000Z",
"epoch": 1469721600,
"owner": "date2",
"categories": [ {
"category": "create_bucket",
"bytes_sent": 19,
"bytes_received": 0,
"ops": 1,
"successful_ops": 1
}
]
},

the time("time": "2016-07-28 16:00:00.000000Z",) is 16 hours later than Local
time: Fri 2016-07-29 08:28:44 CST

i can get the usage show by radosgw-admin usage show --uid=date2
--start-date="2016-07-28 16:00:00"
[root at ceph03 ~]# radosgw-admin usage show --uid=date2
--start-date="2016-07-28 16:00:00" {
"entries": [ {
"user": "date2",
"buckets": [ {
"bucket": "07_29.08_34_42",
"time": "2016-07-28 16:00:00.000000Z",
"epoch": 1469721600,
"owner": "date2",
"categories": [ {
"category": "create_bucket",
"bytes_sent": 19,
"bytes_received": 0,
"ops": 1,
"successful_ops": 1
}
]
}
]
}
],
"summary": [ {
"user": "date2",
"categories": [ {
"category": "create_bucket",
"bytes_sent": 19,
"bytes_received": 0,
"ops": 1,
"successful_ops": 1
}
],
"total": {
"bytes_sent": 19,
"bytes_received": 0,
"ops": 1,
"successful_ops": 1
}
}
]
}
but this radosgw-admin usage show --uid=date2 --start-date="2016-07-28
16:00:01" can not get the usage
[root at ceph03 ~]# radosgw-admin usage show --uid=date2
--start-date="2016-07-28 16:00:01" {
"entries": [],
"summary": []
}

History

#1 Updated by Abhishek Lekshmanan over 6 years ago

  • Project changed from Ceph to rgw
  • Category deleted (22)

#2 Updated by Loïc Dachary over 6 years ago

  • Target version deleted (v10.2.3)

#3 Updated by Yehuda Sadeh over 6 years ago

  • Priority changed from Normal to High

#4 Updated by Yehuda Sadeh over 6 years ago

  • Assignee set to Orit Wasserman

#5 Updated by Yehuda Sadeh over 6 years ago

  • Assignee changed from Orit Wasserman to Matt Benjamin

#6 Updated by Matt Benjamin over 6 years ago

  • Status changed from New to In Progress

#7 Updated by Matt Benjamin over 6 years ago

Some status: in my current attempts to reproduced, I see slightly different behavior:
1. after adding "rgw enable usage log = true"
2. creating an object in a bucket
3. reported time on the bucket appeared was NOT skewed in the past, BUT
4. instead reporting as a fixed time in the past--possibly rounded

#8 Updated by Matt Benjamin about 6 years ago

Status update:
I'm still confirming invariants in the code. 1) By instrumenting UsageLogger::add_user, I caused a log of all new epochs for a bucket to be printed; 2) By instrumenting rgw_user_usage_log_add, I caused the new epoch values being sent from the same client to be printed. 3) By inspection,

I expected the highest value printed in #1 to reach the print at #2 after all updates to a specific buckets have completed and radosgw and osds have quiesced; I also expected the epoch value printed for that bucket in "radosgw-admin -c ${CONF} usage show" to a) match and b) hold the highest value seen in #1 (and #2) at the same point. What I actually observe is matching values at #2 and #3, both LOWER than the highest value I observe at #1. Looking to confirm, usage logging is lossy?

#9 Updated by Matt Benjamin about 6 years ago

  • Priority changed from High to Low

Revised status:
The obvious reason the highest epoch value is not stored is that currently the epoch value is rounded downward to the nearest hour. There is no other time formatting until display, when the epoch value is formatted in UTC. As the epoch value is also present, this seems harmless.

Responding to myself in comment #8, the usage log is async/non-blocking, and weakly consistent: outgoing usage log records are stored in memory and flushed to RADOS at the configured rgw_usage_log_tick_interval (default 30s), or earlier if a threshold fill is reached.

Additional information on output formats could perhaps be added to the admin guide and the Logging Settings section on the configuration guide, as the consistency model and current rounding behavior do not seem to be documented.

Please update with more concrete reproducer information if there is still suspicion of a bug.

Also available in: Atom PDF