Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

start_time in _replicate response not using UTC #1841

Closed
skeyby opened this Issue Jan 3, 2019 · 11 comments

Comments

Projects
None yet
3 participants
@skeyby
Copy link

skeyby commented Jan 3, 2019

Invoking the _replicate API endpoint, the JSON response reports a wrong start time - on our server it's 1 hour back in time.

Expected Behavior

start_time should be correct time :)

Current Behavior

after creating two database with just a single document and invoking a single one shot replication for the specific doc id of the document this is the response:

{
"ok": true,
"session_id": "4ae02b10379bd5e8cb4b0ee5eff03275",
"source_last_seq": "1-g1AAAAIReJyVz10OgjAMAOAqJuqjJ9ATGMb4mU9yE-3oFiSITzzrTfQmehO9CQ4xARKDkCVd0rVfuxQAZrFFsIhOeRSTDJkTrG1zWGqexghyWRRFElsIR5OY2n6AXAQE8zwjpQ-Zoo52uTJRbr_C6CP46CnJxa-eLikspV1rF47CkUz13WVfCueWsNHCJZI9hWxiIlzMZZBrrRBqxpU_SLlVyj1B-Fv7qGqf9USHuQxdPWjiq1Iavxfocy_iTSV5A4-ckCc",
"replication_id_version": 4,
"start_time": "Thu, 03 Jan 2019 15:43:48 GMT",
"end_time": "Thu, 03 Jan 2019 16:43:55 GMT",
"docs_read": 1,
"docs_written": 1,
"doc_write_failures": 0,
"history": [
{
"session_id": "4ae02b10379bd5e8cb4b0ee5eff03275",
"start_time": "Thu, 03 Jan 2019 15:43:48 GMT",
"end_time": "Thu, 03 Jan 2019 16:43:55 GMT",
"start_last_seq": 0,
"end_last_seq": "1-g1AAAAIReJyVz10OgjAMAOAqJuqjJ9ATGMb4mU9yE-3oFiSITzzrTfQmehO9CQ4xARKDkCVd0rVfuxQAZrFFsIhOeRSTDJkTrG1zWGqexghyWRRFElsIR5OY2n6AXAQE8zwjpQ-Zoo52uTJRbr_C6CP46CnJxa-eLikspV1rF47CkUz13WVfCueWsNHCJZI9hWxiIlzMZZBrrRBqxpU_SLlVyj1B-Fv7qGqf9USHuQxdPWjiq1Iavxfocy_iTSV5A4-ckCc",
"recorded_seq": "1-g1AAAAIReJyVz10OgjAMAOAqJuqjJ9ATGMb4mU9yE-3oFiSITzzrTfQmehO9CQ4xARKDkCVd0rVfuxQAZrFFsIhOeRSTDJkTrG1zWGqexghyWRRFElsIR5OY2n6AXAQE8zwjpQ-Zoo52uTJRbr_C6CP46CnJxa-eLikspV1rF47CkUz13WVfCueWsNHCJZI9hWxiIlzMZZBrrRBqxpU_SLlVyj1B-Fv7qGqf9USHuQxdPWjiq1Iavxfocy_iTSV5A4-ckCc",
"missing_checked": 1,
"missing_found": 1,
"docs_read": 1,
"docs_written": 1,
"doc_write_failures": 0
}
]
}

As you can see even if the replication job took just a few seconds there's an hour of difference between start_time and end_time.

end_time was the correct time when the test was executed.

Steps to Reproduce (for bugs)

curl -X PUT "http://127.0.0.1:5984/baseball_1"
curl -X PUT "http://127.0.0.1:5984/baseball_2"
curl -H 'Content-Type: application/json' -X POST "http://127.0.0.1:5984/baseball_1/" -d '{}'
curl -H 'Content-Type: application/json' -X POST "http://127.0.0.1:5984/_replicate" -d '{"source":{"url":"http://10.33.102.165:5984/baseball_1"},"target":{"url":"https://free.bd.gcloud.schema31.it:443/baseball_2"},"doc_ids":[*****FILL WITH THE DOCUMENT ID FROM PREVIOUS POST*****]}'

Your Environment

  • Version used: 2.3.0
  • Operating System and version (desktop or mobile): FreeBSD 11.2 (Erlang Runtime 21.2)
@wohali

This comment has been minimized.

Copy link
Member

wohali commented Jan 7, 2019

I can't confirm this - what is the timezone setting on your server? Erlang should be picking it up from that.

$ curl -X PUT http://127.0.0.1:15984/baseball_1
{"ok":true}
$ curl -X PUT http://127.0.0.1:15984/baseball_2
{"ok":true}
$ curl -H 'Content-Type: application/json' -X POST "http://127.0.0.1:15984/baseball_1/" -d '{}'
$ curl -H 'Content-Type: application/json' -X POST "http://127.0.0.1:15984/_replicate" -d '{"source":{"url":"http://127.0.0.1:15984/baseball_1"},"target":{"url":"https://127.0.0.1:15984/baseball_2"},"doc_ids":["41fa187659bd5957ab3d2d22a80006f4"]}'
{"ok":true,"session_id":"5ac147f405fb75b6b7107d76a14e7c30","source_last_seq":"1-g1AAAAGXeJzLYWBg4MhgTmHgz8tPSTV0MDQy1zMAQsMcoARTIkOS_P___7MymBMZcoEC7BYGlommhhYpDJyleSmpaZl5qSk4NScpAMkke5D-RAbcqhxAquIJqUoAqaonoCqPBUgyNAApoML5hFUugKjcj_CfUWJKqhGR_oOYcQBixn2QGYxgM0wtzC0tk4wwdREw6QHEJJAPswD_amrS","replication_id_version":4,"start_time":"Mon, 07 Jan 2019 21:35:51 GMT","end_time":"Mon, 07 Jan 2019 16:35:56 GMT","docs_read":1,"docs_written":1,"doc_write_failures":0,"history":[{"session_id":"5ac147f405fb75b6b7107d76a14e7c30","start_time":"Mon, 07 Jan 2019 21:35:51 GMT","end_time":"Mon, 07 Jan 2019 16:35:56 GMT","start_last_seq":0,"end_last_seq":"1-g1AAAAGXeJzLYWBg4MhgTmHgz8tPSTV0MDQy1zMAQsMcoARTIkOS_P___7MymBMZcoEC7BYGlommhhYpDJyleSmpaZl5qSk4NScpAMkke5D-RAbcqhxAquIJqUoAqaonoCqPBUgyNAApoML5hFUugKjcj_CfUWJKqhGR_oOYcQBixn2QGYxgM0wtzC0tk4wwdREw6QHEJJAPswD_amrS","recorded_seq":"1-g1AAAAGXeJzLYWBg4MhgTmHgz8tPSTV0MDQy1zMAQsMcoARTIkOS_P___7MymBMZcoEC7BYGlommhhYpDJyleSmpaZl5qSk4NScpAMkke5D-RAbcqhxAquIJqUoAqaonoCqPBUgyNAApoML5hFUugKjcj_CfUWJKqhGR_oOYcQBixn2QGYxgM0wtzC0tk4wwdREw6QHEJJAPswD_amrS","missing_checked":1,"missing_found":1,"docs_read":1,"docs_written":1,"doc_write_failures":0}]}
[688 atypical:joant ~] $ date -u
Mon Jan  7 16:36:47 UTC 2019

Obviously the recommendation is to run with your server set to UTC.

@skeyby

This comment has been minimized.

Copy link
Author

skeyby commented Jan 7, 2019

$ date -u
Mon Jan  7 17:53:08 UTC 2019
$ date
Mon Jan  7 18:53:10 CET 2019

The server is in GMT+1, we're in Rome.

@skeyby

This comment has been minimized.

Copy link
Author

skeyby commented Jan 7, 2019

Sorry Joan but your example confirm my report. Maybe I didn't explain myself correctly.

"start_time":"Mon, 07 Jan 2019 21:35:51 GMT","end_time":"Mon, 07 Jan 2019 16:35:56 GMT"

Your End Time is 5 hours before your start time.

Maybe your replication was called Delorean :-)

@wohali

This comment has been minimized.

Copy link
Member

wohali commented Jan 7, 2019

Ah, this is because the shell from which I launched CouchDB has my TZ set to EST5EDT:

$ echo $TZ
EST5EDT

which is overriding /etc/timezone.

Check the TZ variable for your launch process for CouchDB. If you launched this from the command line, you may have your local

If you're on Linux, you can confirm this by looking in /proc/<pid-of-couchdb>/environ.

Not saying this is fixed, just a workaround.

@wohali wohali changed the title Wrong start_time in _replicate response start_time in _replicate response not using UTC Jan 7, 2019

@wohali

This comment has been minimized.

Copy link
Member

wohali commented Jan 7, 2019

@nickva looks like we have a TZ problem

@nickva

This comment has been minimized.

Copy link
Contributor

nickva commented Jan 7, 2019

@skeyby Thank you for the report!

@wohali , indeed seems like a bug, thanks for digging in and debugging it. I'll assign the ticket to me.

@nickva nickva self-assigned this Jan 7, 2019

@skeyby

This comment has been minimized.

Copy link
Author

skeyby commented Jan 8, 2019

Ah, this is because the shell from which I launched CouchDB has my TZ set to EST5EDT:

$ echo $TZ
EST5EDT

which is overriding /etc/timezone.

Check the TZ variable for your launch process for CouchDB. If you launched this from the command line, you may have your local

If you're on Linux, you can confirm this by looking in /proc/<pid-of-couchdb>/environ.

Not saying this is fixed, just a workaround.

Hi Joan. Just as a general note, FreeBSD neither have /etc/timezone or $TZ environment variable.

I guess Erlang is finding the correct timezone somehow else.

Thanks.

@wohali

This comment has been minimized.

Copy link
Member

wohali commented Jan 8, 2019

Hi @skeyby ,

Ah, didn't realize you were on FreeBSD. In this case it's using what's at /etc/localtime:

cd /usr/share/zoneinfo/ && find * -type f -exec cmp -s {} /etc/localtime \; -print;

will tell you what you have it set to.

You can simply cp /usr/share/zoneinfo/UTC /etc/localtime to work around this for now if you want. Of course, all times in your shell will now be in UTC instead of in GMT+1.

nickva added a commit that referenced this issue Jan 8, 2019

Fix end_time field in /_replicate response
Previously `end_time` was generated converting the start_time to universal,
then passing that to `httpd_util:rfc1123_date/1`. However, `rfc1123_date/1`
also transates its argument from local to UTC time, that is it accepts input to
be in local time format.

Fixes #1841
@nickva

This comment has been minimized.

Copy link
Contributor

nickva commented Jan 8, 2019

@skeyby @wohali I tried to fix it in #1845 give it a try and see if it works on your machines

@nickva nickva closed this in #1845 Jan 8, 2019

nickva added a commit that referenced this issue Jan 8, 2019

Fix end_time field in /_replicate response
Previously `end_time` was generated converting the start_time to universal,
then passing that to `httpd_util:rfc1123_date/1`. However, `rfc1123_date/1`
also transates its argument from local to UTC time, that is it accepts input to
be in local time format.

Fixes #1841
@skeyby

This comment has been minimized.

Copy link
Author

skeyby commented Jan 9, 2019

@skeyby @wohali I tried to fix it in #1845 give it a try and see if it works on your machines

Hi Nick,

unfortunately I don't have a "development" machine where I can easily try the fix.

BTW the wrong field was start time (and in fact that is the one you corrected in the code) not the end time you referenced in the commit message...

@nickva

This comment has been minimized.

Copy link
Contributor

nickva commented Jan 9, 2019

@skeyby Argh it looks like I put the wrong commit message in. It is fixing the start time in the code:

https://github.com/apache/couchdb/pull/1845/files

The problem previously was that start_time was kept internally as a "system" timestamp. Then we translated that to the "universal" time and then called another function which translated from local to the universal. So it applied the same transformation twice.

janl added a commit that referenced this issue Feb 7, 2019

Fix end_time field in /_replicate response
Previously `end_time` was generated converting the start_time to universal,
then passing that to `httpd_util:rfc1123_date/1`. However, `rfc1123_date/1`
also transates its argument from local to UTC time, that is it accepts input to
be in local time format.

Fixes #1841

janl added a commit that referenced this issue Feb 17, 2019

Fix end_time field in /_replicate response
Previously `end_time` was generated converting the start_time to universal,
then passing that to `httpd_util:rfc1123_date/1`. However, `rfc1123_date/1`
also transates its argument from local to UTC time, that is it accepts input to
be in local time format.

Fixes #1841
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.
You signed in with another tab or window. Reload to refresh your session. You signed out in another tab or window. Reload to refresh your session.