Duplicate Orders

[RodG]

my guess is a problem with sending of emails.

Spot on. In fact I'd just logged in here to report that I'd identified this as the problem.

I've not fixed it yet (not looked), I thought I'd take a little bit of 'time out' to celebrate.

Yeah, some may say it's a little premature - but having identified the process causing the delay is as good as a solution AFAIK. :-)

i bet if you placed an order with email notifications turned off the response time would be about a second... again just a guess...

I've not done this particular test/experiment yet, but I was able to confirm/verify this with the order update function, so yeah, basically the same test/proof.

What *eventually* 'clicked' for me was that the problem only occurred (or seemed to only occur) with the order confirmation and the order update functions. For over a week I've been puzzling over what the common denominator was with these two functions, and it just 'hit' me while I was waiting for another update to return, and from then it was easy to 'prove'. :-)

My next question @carlwhat is, Where the heck were you with this suggestion a few days ago? <g>

Seriously though, although an hour or two 'late' I really do appreciate the response/suggestion. I 'knew' that if anyone would come up with a viable explanation it would be another Zenner :-)


Cheers
RodG

[carlwhat]

My next question @carlwhat is, Where the heck were you with this suggestion a few days ago? <g>

- working on my PCI compliance. ;)
- still mourning the loss of David Bowie.
- wondering how people at themeforest could charge for 1.5.4 responsive design templates that work like crap with bugs and outdated code from older releases.
- debugging (yet again) the crap (IMHO) that is MY_ADMIN/includes/functions/extra_functions/edit_orders_functions.php.

shall i go on?

seriously, as i stated in the link that i provided, i think it's #1 a design flaw that despite the settings one has, ZC will create the order without clearing the cart. the idea that sending an email order confirmation in the middle of that process which could derail the process is inherently bad... again IMHO. and #2 using the built-in ZC logging function would have saved us both many hours of time and frustration as it would have pointed us both in the right direction as to the cause of the problem.

glad you were able to identify the problem. indeed, identifying the problem is much more difficult and worthy of celebration that implementing a solution.

[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.