Resolved Some VirtueMart orders not exported due to time zone issues

Hello,

It seems like that CSVI's post processing is not handling time zones properly. When we run the SQL query found in the debug results, we get all orders that we are expecting, including the missing ones. Only the actual CSV file generated doesn't include the missing ones.

This cannot be possible, the records you get in export query is what written to export file as there is no post processing in CSVI. I am thinking this could be something to do with your group by fields, what if you remove the group by fields you have now and just add virtuemart_order_id? do you still see missing records? If yes, can you paste the query you tried to run manually and explain in detail with screenshots on the records you see in running the query and the missing ones?

Couldn't be group by as running the query manually shows all the records correctly including the missing ones.

The query used is the one from the debug results, please see attached "query.txt".

Basically, we change the part that says "DATE_SUB(CURDATE(), INTERVAL 1 DAY)" to the actual date like "2016-12-08" to test.

As for the example, please see attached "results.txt". Kindly take note that personal information have been removed.

The last order, O-1612-12910 - 2016-12-03 23:38:33 shows properly when running the query manually but doesn't show in the CSV exported.

To add, the created_on records in #__virtuemart_orders.created_on are written in UTC but when the CSV is generated, they are written in UTC+8.

Having said the above, we assume that there is a post process as there's nothing in the query that converts time zones.

Hello,

Basically, we change the part that says "DATE_SUB(CURDATE(), INTERVAL 1 DAY)" to the actual date like "2016-12-08" to test.

Which is odd because the query

DATE_SUB(CURDATE(), INTERVAL 1 DAY)

also gets you the actual date in the format of 2016-12-07. So I don't think this is the issue you are seeing.

What we noticed is that the missing orders all have an order time (created_on field) of 23:xx:xx.

This means you are missing the last hour and with a timezone of UTC+8, that would mean you are missing 8 hours if your timezone was the issue. What strikes me as odd is that only the last hour of the day is missing, that should not be possible when filtering on a date.

Looking at the debug log it shows you ran the export at 23:22:02, now the order is from 23:38:33. When is your export scheduled to run? What is the date and timestamp you get when you run this SQL query

select now();

I think the root cause may lie here.

To add, the created_on records in #__virtuemart_orders.created_on are written in UTC but when the CSV is generated, they are written in UTC+8.

Correct, CSVI converts the dates to the current timezone set in Joomla.

We are only changing "DATE_SUB(CURDATE(), INTERVAL 1 DAY)" to a fixed date as the missing records happened in the past thus "CURDATE()" will mean today.

The cron runs every 7 am. As of this writing, "SELECT NOW()" shows "2016-12-08 16:59:25".

We are now trying to run it every 8 am instead to see if it will help.

Hello,

We are only changing "DATE_SUB(CURDATE(), INTERVAL 1 DAY)" to a fixed date as the missing records happened in the past thus "CURDATE()" will mean today.

Both CURDATE() and DATE_SUB(CURDATE(), INTERVAL 1 DAY) return a fixed date. The INTERVAL 1 DAY subtracts 1 day from the value returned by CURDATE().

We are now trying to run it every 8 am instead to see if it will help.

That may actually help because of the UTC+8 timezone you are in.

Let me know how it goes.

Yes, we are aware of what the function does. It was just mentioned as the results will be different if it was ran today vs tomorrow and so on so we use fixed dates when testing.

It's important to note that the missing records don't show even in the next CSV exported (next day's cron run).

We are using CSVI's "yesterday" date range option so we are expecting to see the missing records in the next CSV exported if they didn't appear in the first one but it is not what happens.

Hello,

It's important to note that the missing records don't show even in the next CSV exported (next day's cron run).

That is odd as well.

We are using CSVI's "yesterday" date range option so we are expecting to see the missing records in the next CSV exported if they didn't appear in the first one but it is not what happens.

When looking into this I have began wondering if the time in the created time stamp is of any influence here. Currently I am also doing some more testing here to see if I can find anything peculiar.

Honestly, it makes no sense to me that putting 2016-12-07 hardcoded in the query gives a different result than DATE_SUB(CURDATE(), INTERVAL 1 DAY) which also gives you that value. I am sure we will find out at some point

No, no - you are right that the function produces the same result as the fixed date as it gives you the same value "if you run it on the correct day". That's the reason why I mentioned "when testing" as we cannot test a day that happened in the past using a function with "CURDATE()" as for example, I wanted to test for 2016-12-01 then if I use the function, it will be 2016-12-08 - 1 day which is 2016-12-07.

Anyway, I hope that we can find a solution to this time zone issue soon.

Here's what we found:

We are trying to export yesterday's orders. Let's say that the steps below started on 2016-12-05 (UTC+8, Asia/Singapore).

1. A CSV was exported on 2016-12-04 23:22:00 UTC and the same timestamp was written to the database and CSVI debug as Joomla is writting UTC time (even though we set it to use UTC+8 on the configurations page). The export used the function DATE_SUB(CURDATE(), INTERVAL 1 DAY) which translates to DATE_SUB('2016-12-05', INTERVAL 1 DAY) = '2016-12-04' as our server, PHP, MySQL, etc. are using UTC+8.

2. A new order was made on 2016-12-04 23:38:00 UTC and the same timestamp was written on the database. This new order was NOT included in the CSV exported above as it happened after the export.

3. The next day, 2015-12-06 (UTC+8, Asia/Singapore), a new CSV similar to no. 1 was exported. The export used the same function, DATE_SUB(CURDATE(), INTERVAL 1 DAY) which translates to DATE_SUB('2016-12-06', INTERVAL 1 DAY) = '2016-12-05'. The export still did NOT show the order that was made in no. 2 as the order was made on 2016-12-04 not on 2016-12-05.

In order to fix this, we think that CSVI should not be using DATE_SUB(CURDATE(), INTERVAL 1 DAY) directly in the query as CURDATE() will use the server's time zone (UTC+8) which causes issues like demonstrated above.

CSVI should convert the timestamp to UTC first so that it is consistent with the timestamps that Joomla is using before passing it to the query or maybe set MySQL's session time zone first then use CONVERT_TZ().

Hello,

Thank you for this in-depth analysis. This clearly explains where the pain is, so I will work on a patch for you. I will let you know when this is ready.

Hello,

I do have some additional questions just to make sure I get things right.

So what you are saying is the following:
The export runs at 7:22am on 2016-12-05 (UTC+8) which for CSVI is 11:22pm on 2016-12-04 (UTC). CSVI exports all orders with a date of 2016-12-03 (UTC date minus 1 day).

The next export runs at 7:22am on 2016-12-06 (UTC+8) which for CSVI is 11:22pm on 2016-12-05 (UTC). CSVI exports all orders with a date of 2016-12-04 (UTC date minus 1 day).

There is basically a 2-day gap there.

Do I understand this correct?

At 7:22am on 2016-12-05 (UTC+8) you can never export all the orders of 2016-12-04 UTC since that day hasn't finished yet, it still has 38 minutes to go.

The export runs at 7:22am on 2016-12-05 (UTC+8) which for CSVI is 11:22pm on 2016-12-04 (UTC). CSVI exports all orders with a date of 2016-12-03 (UTC date minus 1 day).

No, CSVI will filter using 2016-12-04 as it directly ran a query through our database server which is using UTC+8 thus it'll be 2016-12-05 - 1 day = 2016-12-04. 2016-12-04 is really UTC+8 but it is used together with UTC dates (Joomla, VirtueMart, etc.) which causes the issue.

At 7:22am on 2016-12-05 (UTC+8) you can never export all the orders of 2016-12-04 UTC since that day hasn't finished yet, it still has 38 minutes to go.

The remaining minutes of the day left doesn't matter as it's logical that there will be orders happening after the CSV has been exported. The issue is that the affected orders doesn't even show in future CSV exports.

Hello,

Please find attached the patch file that I believe should fix the issue. I have replaced CURDATE() with the UTC datestamp.

Can you please check if this solves your issue?

Thanks.

We have checked the file and the changes will seem to fix the issue.

Thanks a lot for your help!

Hello,

Good to hear things are solved, I will include this fix in the next release.