Duplicate Orders

[Friedrich72]

Love Zen Cart. Everything works great except this, kind of big, problem.
We could really use some help determining the cause of random, duplicate orders.
I have installed a few Zen Cart stores and this is the only one that has the problem.
This store is different in that it receives a lot of traffic compared to the others. And there are some different modules installed.

ZC: 1.5.1
Upgraded: from 1.3.9h to 1.5.1 on April 9 in hopes that it would solve the duplicate orders problem.
PHP: 5.2.17
Host: 1and1
Mods:

• ceon adv shipper 5.x
• ceon manual card
• image handler 4
• column layout grid
• edit orders 4.0.4
• Zen Lightbox 1.6.3
• Minimum Order

Performed Manual Install via Filezilla
We don't use paypal or any other type of processing than listed above.

I have read through this thread http://www.zen-cart.com/showthread.p...-Confirmation/ and it sounds like the same problem except our problem is also with 1.5.1

This is what happens:
Maybe 5 times a month roughly an order is duplicated at the time of purchase or a few seconds after, or a few minutes after.
The customer is only charged once.
The customer receives a notification on the second order.
Same order number on duplicate.

Suspicion:
possibly host processing lag is causing it
1and1 seemed to have slow processing time on their secure server. I contacted them. They confirmed that they were dealing with some issues. I asked them if the duplicates could be attributed to it but they said no.

Can someone tell me the best way to analyze what is happening?
I need something like the error log that is built into ZC.
However there are no errors in that log resulting from the duplicates.

Is anyone else from the thread link above still having issues?

[DrByte]

This is what happens:
Maybe 5 times a month roughly an order is duplicated at the time of purchase or a few seconds after, or a few minutes after.
The customer is only charged once.
The customer receives a notification on the second order.
Same order number on duplicate.

The only payment module you've mentioned is CEON Manual Order ... which merely emails the encrypted card number, immediately, no time delay.
So, since an order is saved/generated immediately after the payment module completes, then your problem is either:
- customer is submitting payment multiple times
- or you're using another payment module or some other addon that's triggering something else to happen in addition to normal operation
The way the core of ZC works it's impossible for a "duplicate" to be generated several minutes later unless something outside normal core code, or an external service, is causing it.

But without seeing timestamps and IP addresses and module info etc of actual orders, we can't do anything other than hypothesize. You've got all the facts.

[Friedrich72]

Thank you for responding, Dr. Byte. Direction like this, from you, is so appreciated!
I have orders from April for the last five duplicates.
What else do we need to pin point the problem? I am thinking of doing a test where we would disable the edit orders module except for certain times when we need it. Do you think that would be helpful?
All but the second one in the list used credit.

99.66.1.26
Tue Apr 30 2013 12:37:01
Tue Apr 30 2013 12:37:06

70.45.115.131 - this one used check
Sat Apr 27 2013 9:00:34
Sat Apr 27 2013 9:00:26

96.248.6.178
Fri Apr 26 2013 14:38:01
Fri Apr 26 2013 14:37:52

108.227.141.135
Tue Apr 23 2013 17:57:36
Tue Apr 23 2013 17:57:26

50.82.241.218
Mon Apr 22 2013 21:46:30
Mon Apr 22 2013 21:46:15

[DivaVocals]

Thank you for responding, Dr. Byte. Direction like this, from you, is so appreciated!
I have orders from April for the last five duplicates.
What else do we need to pin point the problem? I am thinking of doing a test where we would disable the edit orders module except for certain times when we need it. Do you think that would be helpful?
All but the second one in the list used credit.

99.66.1.26
Tue Apr 30 2013 12:37:01
Tue Apr 30 2013 12:37:06

70.45.115.131 - this one used check
Sat Apr 27 2013 9:00:34
Sat Apr 27 2013 9:00:26

96.248.6.178
Fri Apr 26 2013 14:38:01
Fri Apr 26 2013 14:37:52

108.227.141.135
Tue Apr 23 2013 17:57:36
Tue Apr 23 2013 17:57:26

50.82.241.218
Mon Apr 22 2013 21:46:30
Mon Apr 22 2013 21:46:15

Edit Orders doesn't affect checkout IN ANY WAY. It is a post order editing module so disabling it won't solve your issue..

[DrByte]

This is where I would start if my site was doing something unexpected: http://www.zen-cart.com/wiki/index.p...Obscure_Issues

And I'd also be comparing the server's apache access-log activity for those specific order timestamps, and then trace all the requests from those IPs to recreate the clicks and redirect patterns, to establish the actual actions that were happening.

[Friedrich72]

Thanks you both! Edit orders is extremely helpful for us so we are relieved not to have to disable it. I will look into your recommendations, Dr Byte.

[Friedrich72]

Ok, I have a few results from the logs.
After getting a program that can handle the log files, Edit Pad Lite, I was able to view what appears to be duplicate, and our first Triple, POST entries.

These two lines occur at the time of purchase, back to back.

70.45.115.131 - - [27/Apr/2013:09:00:08 -0400] "POST /store/index.php?main_page=checkout_process HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_confirmation" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; SIMBAR Enabled; SIMBAR={948EF965-EBC3-4e95-A9B5-E54E2F7B5B4A}; SIMBAR=0; FunWebProducts; GTB7.4; .NET CLR 1.1.4322; InfoPath.1; BRI/2)" "-"

70.45.115.131 - - [27/Apr/2013:09:00:18 -0400] "POST /store/index.php?main_page=checkout_process HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_confirmation" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; SIMBAR Enabled; SIMBAR={948EF965-EBC3-4e95-A9B5-E54E2F7B5B4A}; SIMBAR=0; FunWebProducts; GTB7.4; .NET CLR 1.1.4322; InfoPath.1; BRI/2)" "-"

These two lines are from time of purchase and separated by 8 other log entries from 3 different users

96.248.6.178 - - [26/Apr/2013:14:37:41 -0400] "POST /store/index.php?main_page=checkout_process HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_confirmation" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; OfficeLiveConnector.1.5; OfficeLivePatch.1.3; .NET4.0C; msn OptimizedIE8;ENUS)" "-"

96.248.6.178 - - [26/Apr/2013:14:37:52 -0400] "POST /store/index.php?main_page=checkout_process HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_confirmation" "Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; OfficeLiveConnector.1.5; OfficeLivePatch.1.3; .NET4.0C; msn OptimizedIE8;ENUS)" "-"

These two are separated by 38 entries made by 1 other user

50.82.241.218 - - [22/Apr/2013:21:46:06 -0400] "POST /store/index.php?main_page=checkout_process HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_confirmation" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" "-"

50.82.241.218 - - [22/Apr/2013:21:46:13 -0400] "POST /store/index.php?main_page=checkout_process HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_confirmation" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" "-"

Here is a more recent one that is our first Triple! What's up with all of the 408's??

172.0.129.90 - - [14/May/2013:19:40:51 -0400] "POST /store/index.php?main_page=checkout_payment_address HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_payment_address" "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)" "-"

172.0.129.90 - - [14/May/2013:19:42:43 -0400] "POST /store/index.php?main_page=checkout_confirmation HTTP/1.1" 200 31411 www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_payment" "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)" "-"

172.0.129.90 - - [14/May/2013:19:44:26 -0400] "POST /store/index.php?main_page=checkout_process HTTP/1.1" 200 - www.mystore.com "https://www.mystore.com/store/index.php?main_page=checkout_confirmation" "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)" "-"

172.0.129.90 - - [14/May/2013:19:43:06 -0400] "-" 408 - - "-" "-" "-"
172.0.129.90 - - [14/May/2013:19:43:06 -0400] "-" 408 - - "-" "-" "-"
172.0.129.90 - - [14/May/2013:19:44:47 -0400] "-" 408 - - "-" "-" "-"
172.0.129.90 - - [14/May/2013:19:46:34 -0400] "-" 408 - - "-" "-" "-"
172.0.129.90 - - [14/May/2013:19:47:48 -0400] "-" 408 - - "-" "-" "-"
172.0.129.90 - - [14/May/2013:19:47:48 -0400] "-" 408 - - "-" "-" "-"

What do you recommend that I look for?
The entries don't appear to be unusual that I can tell, but this is the first time I have looked at logs in this way.
We are getting complaints of slow order processing. We have also personally observed slow processing at times. But not every time...

[lhungil]

The "HTTP 408 Request Timeout" usually indicates the web server has 'timed out'. Basically the web server believes it has been waiting too long for the client (browser) to download data (page) from the web server... And the server has closed the connection. I would expect to see the browser retry the request when this occurs....

So either clients on REALLY slow / broken internet connections... Something going on with network routing / communications between the client and the server... or something going on with the web server...

Do you know if the "HTTP 408" could be a symptom of the performance issues 1and1 are trying to correct?

[Friedrich72]

Thanks for the response, lhungil. I spoke with 1and1 today and they went through the order process with me. Of course, there were no errors or extreme lag when we did.
The 408 errors and duplicates/triplicates could still be caused by a secure server issue.
They told me that in order to elevate the ticket they need to be able to reproduce the error.
I sent them error logs that show the problems and they said they will continue to test the ordering process.

As an amendment to my original post: I said the order number on the duplicates is the same. That is not correct. A new order number is created when the duplicate "order confirmation" page info is posted.

In the mean time the problem persists and we received our second triplicate just a few days ago.

[RodG]

Hi DrB (and others)

I know this is a rather old thread that doesn't seem to be resolved, but I've got both a similar and identical problem that frankly has be somewhat stumped.

The 'upside' is that both problems are easy for me to replicate and are very consistant. Alas, this doesn't seem to be helping me.

Two stores on the same server:

Store#1 works perfectly in every way *except* when I hit the button to update an orders status (doesn't matter what order). It just hangs - For almost two minutes before the the screen refreshes with the update succeful message. If I re-press the button before it returns I'm greeted with a message along the lines of 'nothing to update'.

Store#2 has a different problem - No problem with the order updates, but there is a huge delay btween the time the 'confirm order' button is pressed and the 'checkout success' page is shown - Typically about 1 minute - but after patiently waiting, it has taken up to 3 minutes. The actual order gets processed and updated into the database almost instantly - it is only the 'checkout success page that is slow. Performing a refresh before the success page is shown results in a duplicate order - Most customers aren't waiting this 1-3mins (I can't blame them) so almost every order is being duplicated.

I'm NOT having these issues with the same sites hosted on another server. The current server is far from being overloaded in any way - it a VPS with 5gb Ram and 4 cores. The other VPS server that I've set up to test/compare with only has 2gb RAM and 2 cores - IOW, about half of the resources than the server with the problems.

Oh, it makes no difference what payment or shipping methods are chosen. The site usually uses the FEC module (has done for years), but the problem persists no matter if I use FEC in single or multiple page checkout mode, and it even persists using the native zencart checkout - In short - Regardless of the chackout method/options - as soon as that 'confirm' button is hit, the order is processed, but the 'checkout success' page doesn't appear for thew 1-3 minutes.

The way the core of ZC works it's impossible for a "duplicate" to be generated several minutes later unless something outside normal core code, or an external service, is causing it.

That's what *I* thought.

But without seeing timestamps and IP addresses and module info etc of actual orders, we can't do anything other than hypothesize. You've got all the facts.

I've got these (from both servers). Not much help really though - other than to confirm the delay.

------------- Server with problem --------------------------------
[24/Jan/2016:13:28:31 +1100] "POST /index.php?main_page=checkout_process HTTP/1.1" 302 20
"http://www.xxxxxxx.com/index.php?main_page=fec_confirmation&fecaction=process" "Mozilla/5.0 (X11; Linux x86_64)


[24/Jan/2016:13:30:03 +1100] "GET /index.php?main_page=checkout_success HTTP/1.1" 200 19763
"http://www.xxxxxx.com/index.php?main_page=fec_confirmation&fecaction=process" "Mozilla/5.0 (X11; Linux x86_64)



Note: This example shows ~90 seconds elapsed between the 'checkout_process' and the 'checkout_success'.


----- Testing server - No problem. --------------------------------
[23/Jan/2016:21:41:05 -0500] "POST /index.php?main_page=checkout_process HTTP/1.1" 302 20
"http://www2.xxxxxx.com.au/index.php?main_page=fec_confirmation&fecaction=process" "Mozilla/5.0 (X11; Linux x86_64)


[23/Jan/2016:21:41:06 -0500] "GET /index.php?main_page=checkout_success HTTP/1.1" 200 19704
"http://www2.xxxxxx.com/index.php?main_page=fec_confirmation&fecaction=process" "Mozilla/5.0 (X11; Linux x86_64)

Note: A mere 1second had elapsed between the 'checkout_process' and the 'checkout_success'.

I'm confident that this isn't technically a ZenCart issue (same code both sites), and if it were a server overload issue (my initial thoughts) then I'd have expected the problem to worsen on the lower powered VPS (besides, logs and graphs indicate that the troublesome server is barely using 5% of its CPU with lots of unutilised RAM (nothing swapping to disk).

There doesn't appear to be any other slowdowns in any other aspect of any of these sites - The problem(s) appears to be pretty specific and consistant to these functions.

All in all, this problem really isn't making any sense to me at all. I can see/observe the problems, but I can't explain how or why they are occurring. (Or why the two sites on the same server are giving different symptoms).

I realise that now I've come this far of setting up another VPS for testing/comparison I could quite easily update the DNS and make this the 'live' site (and solve the problem(s) - And I suspect it may even come to that anyway, BUT, computers aren't 'magical black boxes' - There *has* to be a logical explanation.

Any ideas? Anyone? (Even speculation could be useful).

I don't even know the next step to fault finding this one. Suggestions?

Oh, I should add this problem just started 'out of the blue' (Mid December).

Thanks for any input.

Cheers
RodG