657290 - Incorrect time saved to DB when attachment added trough XML-RPC

Status: RESOLVED FIXED

(Bugzilla :: WebService, defect, P2)

Description

[Konstantin Petrukhnov]

User-Agent:       Mozilla/5.0 (Windows NT 6.1; WOW64; rv:2.0.1) Gecko/20100101 Firefox/4.0.1
Build Identifier: Bugzilla 4.0.1

When attachment added right after bug was created, sometimes it leads to situation when attachment is shown before 1st comment (description).

I looked in database and have next data (table.column: value):
attachments.creation_ts: 10:09:40
bugs.creation_ts: 10:09:37
bugs.delta_ts: 10:09:00
bugs.last_diffed: 10:09:41


- comment -
longdescs.comment_id: 58
longdescs.bug_when: 10:09:37

- attachment -
longdescs.comment_id: 59
longdescs.bug_when: 10:09:00
 
When I look to page, attachment info is shown in Description with time: 2011-05-16 10:09:00 EEST 
And description shown as 1st comment with time: 2011-05-16 10:09:37 EEST 

If I update attachment description it updated in bug description. But Bug.description time remain same.

I made few tests, and it happened in 80% of cases for me.

Reproducible: Sometimes

Steps to Reproduce:
Trough XML-RPC
1. add bug and attachment to it with short delay (less than 1 min)

Actual Results:  
Attachment shown before original bug description.

Expected Results:  
Attachment should be shown after bug description.

All attempts to work with description and comments become incorrect.

One workaround is to add 61second delay before adding attachments... but if there is need to add 60 bugs with attachments -> it will be already more than 1 hour...

Comment 1

[Max Kanat-Alexander]

That is very strange and should not be possible. Is there a difference in the time on your web server and database server?

Also, I assume you're calling Bug.create and then Bug.add_attachment?

Comment 2

[Konstantin Petrukhnov]

Apache2.2 and Mysql5 are at the same server (both have timezone UTC+2). Server is VMWare image, maybe this affect somehow?

I have next sequence.
Bug.create
Bug.get(last_change_time)
Bug.add_attachment

Comment 3

[Max Kanat-Alexander]

(In reply to comment #2)
> Bug.get(last_change_time)

  What does that mean?

Comment 4

[Konstantin Petrukhnov]

It mean that i get this field for created bug, before adding attachments.

Comment 5

[Max Kanat-Alexander]

Okay. Very strange. I just checked the code, and indeed as far as Bugzilla's concerned, what you're describing is impossible. There's a transaction that wraps the entire bug-creation process, so the bug id can't be visible to Bug.get until that's done.

What timezone is your system in *specifically*? That is, what's the Foo/Bar code for your timezone? (Like Europe/Zurich, etc.)

If you do "SELECT NOW();" in your database, does it give you the wrong time?

Comment 6

[Konstantin Petrukhnov]

Sorry that i wasn't clear enough. Bug creation process is fine. 
The problem is, that only attachments get incorrect time. It added after bug is created, but "longdescs.bug_when" field for that attachment have time in past. Attachment added at 10:09:40, but in database time is 10:09:00.

Comment 7

[Konstantin Petrukhnov]

Here is some additional information: 
Timezone is Europe/Helsinki
Server time: Thu May 19 08:34:55 EEST 2011
DB time: 2011-05-19 08:34:55

Here is list of installed perl modules and their versions:
Checking perl modules...
Checking for               CGI.pm (v3.51)     ok: found v3.53
Checking for           Digest-SHA (any)       ok: found v5.47
Checking for             TimeDate (v2.21)     ok: found v2.23
Checking for             DateTime (v0.28)     ok: found v0.52
Checking for    DateTime-TimeZone (v0.71)     ok: found v1.10
Checking for                  DBI (v1.41)     ok: found v1.609
Checking for     Template-Toolkit (v2.22)     ok: found v2.22
Checking for           Email-Send (v2.00)     ok: found v2.198
Checking for           Email-MIME (v1.904)    ok: found v1.907
Checking for                  URI (any)       ok: found v1.52
Checking for       List-MoreUtils (v0.22)     ok: found v0.25_02

Checking available perl DBD modules...
Checking for               DBD-Pg (v1.45)     not found
Checking for            DBD-mysql (v4.00)     ok: found v4.012
Checking for           DBD-Oracle (v1.19)     not found

The following Perl modules are optional:
Checking for                   GD (v1.20)     ok: found v2.39
Checking for                Chart (v2.1)      ok: found v2.4.1
Checking for          Template-GD (any)       ok: found v1.56
Checking for           GDTextUtil (any)       ok: found v0.86
Checking for              GDGraph (any)       ok: found v1.44
Checking for             XML-Twig (any)       ok: found v3.32
Checking for           MIME-tools (v5.406)    ok: found v5.427
Checking for          libwww-perl (any)       ok: found v5.834
Checking for          PatchReader (v0.9.4)    ok: found v0.9.6
Checking for            perl-ldap (any)       ok: found v0.4001
Checking for          Authen-SASL (any)       ok: found v2.15
Checking for           RadiusPerl (any)       ok: found v0.17
Checking for            SOAP-Lite (v0.712)    ok: found v0.712
Checking for             JSON-RPC (any)       ok: found v0.96
Checking for              JSON-XS (v2.0)      ok: found v2.27
Checking for           Test-Taint (any)       ok: found v1.04
Checking for          HTML-Parser (v3.40)     ok: found v3.64
Checking for        HTML-Scrubber (any)       ok: found v0.08
Checking for Email-MIME-Attachment-Stripper (any)       ok: found v1.316
Checking for          Email-Reply (any)       ok: found v1.202
Checking for          TheSchwartz (any)       ok: found v1.07
Checking for       Daemon-Generic (any)       ok: found v0.61
Checking for             mod_perl (v1.999022) not found
Checking for     Apache-SizeLimit (v0.93)     not found
Checking for   Math-Random-Secure (v0.05)     not found

Comment 8

[Frédéric Buclin]

I can consistently reproduce the issue. Calling Bug.create() followed by Bug.add_attachment() gives these results:

mysql> select creation_ts, delta_ts from bugs where bug_id = 2192;
+---------------------+---------------------+
| creation_ts         | delta_ts            |
+---------------------+---------------------+
| 2011-12-03 21:46:14 | 2011-12-03 21:46:00 |
+---------------------+---------------------+
1 row in set (0.00 sec)

mysql> select bug_when, thetext, extra_data from longdescs where bug_id = 2192;
+---------------------+----------------------+------------+
| bug_when            | thetext              | extra_data |
+---------------------+----------------------+------------+
| 2011-12-03 21:46:14 | problème de timing?  | NULL       |
| 2011-12-03 21:46:00 |                      | 1262       |
+---------------------+----------------------+------------+
2 rows in set (0.00 sec)

mysql> select creation_ts, modification_time, description from attachments where bug_id = 2192;
+---------------------+---------------------+-----------------+
| creation_ts         | modification_time   | description     |
+---------------------+---------------------+-----------------+
| 2011-12-03 21:46:15 | 2011-12-03 21:46:15 | Un comm sur moi |
+---------------------+---------------------+-----------------+
1 row in set (0.00 sec)


So the problem is about longdescs.bug_when and bugs.delta_ts which have seconds truncated from their timestamp. I suspect the root cause is the same, and looks like a bug in Bug.add_attachment().

Comment 9

[Frédéric Buclin]

Ah, the reason is that Bug.add_attachment() calls:

  $_->bug->update($_->attached) foreach @created;

but $->attached returns timestamps with the %Y.%m.%d %H:%i format, i.e without seconds.

Comment 10

[Frédéric Buclin]

Attachment: patch, v1

Comment 11

[David Lawrence [:dkl]]

Comment on attachment 578856 [details] [diff] [review]
patch, v1

Looks good and works as expected. r=dkl

Comment 12

[Frédéric Buclin]

Committing to: bzr+ssh://[e-mail]/bugzilla/trunk/
modified Bugzilla/WebService/Bug.pm
Committed revision 8035.

Committing to: bzr+ssh://[e-mail]/bugzilla/4.2/
modified Bugzilla/WebService/Bug.pm
Committed revision 7978.

Committing to: bzr+ssh://[e-mail]/bugzilla/4.0/
modified Bugzilla/WebService/Bug.pm
Committed revision 7666.