R5-Sp1 Checkout random payment failures

[AbleMods]

We're seeing random failures to process a checkout and have no idea where to look. It's causing the site to be unable to accept orders both admin side and shopper side until the site is reset.

Here's what we do know:

1. We know having LiveAgent javascript chat in any section of the 4 checkout pages causes problems. We have removed it and have seen some improvement but the problem has not gone away. So we're not fully convinced this was an issue but have eliminated it as a possibility nonetheless.

2. We have not been able to determine a time of day or specific admin action that results in the behavior. It can happen in the morning, afternoon or evening.

3. User maintenance is not running at the time checkouts start failing.

4. Once the problem starts, it does not resolve itself. Only a restart of the app pool, restart of IIS or a reboot of the entire server resolves the issue.

5. The problem affects both admin-side and shopper-side ability to checkout. This is a key clue to the problem in my opinion.

Errors in the app.log seem to be the majority of these two examples. This one is from an admin trying to create order:

2013-07-26 08:30:53,003 ERROR AbleCommerce An error has occured at https://www.firefold.com/Admin/Orders/C ... ?UID=11977
System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> System.ArgumentNullException: Value cannot be null.
Parameter name: key
at CommerceBuilder.DomainModel.EntityWithTypedId`1.Save()
at CommerceBuilder.Stores.StoreRepository.GetNextOrderNumber(Boolean increment)
at CommerceBuilder.Stores.StoreDataSource.GetNextOrderNumber(Boolean increment)
at CommerceBuilder.Services.Checkout.CheckoutService.ExecuteCheckout(CheckoutRequest checkoutRequest, Boolean validateBasket)
at AbleCommerce.Admin.Orders.Create.DeferPaymentForm.SubmitButton_Click(Object sender, EventArgs e)
at System.Web.UI.WebControls.Button.RaisePostBackEvent(String eventArgument)
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.HandleError(Exception e)
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest()
at System.Web.UI.Page.ProcessRequest(HttpContext context)
at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

And this one is from the shopper side during the same outage:

2013-07-26 08:36:23,817 ERROR AbleCommerce An error has occured at https://www.firefold.com/Checkout/Payment.aspx
System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> System.ArgumentNullException: Value cannot be null.
Parameter name: key
at CommerceBuilder.DomainModel.EntityWithTypedId`1.Save()
at CommerceBuilder.Stores.StoreRepository.GetNextOrderNumber(Boolean increment)
at CommerceBuilder.Stores.StoreDataSource.GetNextOrderNumber(Boolean increment)
at CommerceBuilder.Services.Checkout.CheckoutService.ExecuteCheckout(CheckoutRequest checkoutRequest, Boolean validateBasket)
at AbleCommerce.ConLib.Checkout.PaymentForms.MailPaymentForm.MailButton_Click(Object sender, EventArgs e)
at System.Web.UI.WebControls.Button.RaisePostBackEvent(String eventArgument)
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.HandleError(Exception e)
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest()
at System.Web.UI.Page.ProcessRequest(HttpContext context)
at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

[ForumsAdmin]

This is R5?

[AbleMods]

Yes R5-SP1

p.s. not getting forum notifications today

[ForumsAdmin]

Baffeled about this one. No clue as why this could be happening. Anyway this is under investigation.

[ForumsAdmin]

Code reviews and strack trace analysis reveals nothing to suspect.

One thing it observe is that probably something goes wrong with the IIS application pool. Possibily when the app not in an active app pool? A later access to the app fails to bring the app pool in correct active state?

Do your logs indicate that the problem starts after a period of inactivity?

[AbleMods]

No inactivity. The site takes 200 orders a day, so it's never slow enough for traffic to stall the app pool.

Always the checkout. Always the payment page. Never any other pages that update tables like basket, category pages etc.

Something is blowing up the ability to read or more likely write the next order number to store settings. Going to put a try catch around the checkout service so we can alert the client sooner.

[ForumsAdmin]

Do you have source for this project?

[ForumsAdmin]

What is frustrating is not being able to reproduce this.

Its a shot in the dark but we suspect something wrong with store settings that are cached... but without being able to reproduce the bug there is no way to confirm.

If you have the source available for this project and you can make the following changes, it can help confirm our suspicion.

Store.cs has this code

Code: Select all

        public virtual StoreSettingsManager Settings
        {
            get
            {
                if (_settings == null)
                {
                    IStoreSettingsProvider provider = AbleContext.Resolve<IStoreSettingsProvider>();
                    _settings = provider.GetSettingsManager(this);
                }
                return _settings;
            }
        }

I propose changing it to

Code: Select all

        public virtual StoreSettingsManager Settings
        {
            get
            {
                if (_settings == null)
                {
                    _settings = new StoreSettingsManager(this);
                }
                return _settings;
            }
        }

Basically we are simply bypassing store settings provider which is responsible for caching the settings.

[egormsen]

Not sure if this is related, but we seeing a similar error on the payment page our store. I noticed it this morning when check the logs. if looking into the log history it has happened about 50 times over the past month, but 45 of them happened over the weekend starting yesterday.

An error has occured at https://store.weighdown.com/Checkout/Payment.aspx
Exception: Exception of type 'System.Web.HttpUnhandledException' was thrown. Stack Trace: at System.Web.UI.Page.HandleError(Exception e) at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) at System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) at System.Web.UI.Page.ProcessRequest() at System.Web.UI.Page.ProcessRequest(HttpContext context) at ASP.checkout_payment_aspx.ProcessRequest(HttpContext context) in c:\Windows\Microsoft.NET\Framework64\v4.0.30319\Temporary ASP.NET Files\root\034f24bf\735d5c2b\App_Web_5m133ba0.14.cs:line 0 at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) Inner Exception: Value cannot be null. Parameter name: key Inner Exception Stack Trace: at CommerceBuilder.DomainModel.EntityWithTypedId`1.Save() at CommerceBuilder.Stores.StoreRepository.GetNextOrderNumber(Boolean increment) at CommerceBuilder.Services.Checkout.CheckoutService.ExecuteCheckout(CheckoutRequest checkoutRequest, Boolean validateBasket) at AbleCommerce.ConLib.Checkout.PaymentForms.CreditCardPaymentForm.CreditCardButton_Click(Object sender, EventArgs e) in c:\inetpub\wwwroot\store\ConLib\Checkout\PaymentForms\CreditCardPaymentForm.ascx.cs:line 243 at System.Web.UI.WebControls.Button.RaisePostBackEvent(String eventArgument) at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)

[AbleMods]

If you have the source available for this project and you can make the following changes, it can help confirm our suspicion.

We have full source code. I will coordinate with the client to implement it. I will post here in a few days once we've had a chance to see it run for a while. The issue can happen 3 times in one day, or only once every 5 days.

Lately it's been more frequent.

p.s. Isn't that going to put quite a load on SQL if we disable caching the store settings for the entire site? These guys get quite a bit of traffic....

[ForumsAdmin]

Joe, Gold R4 did not have this caching for store settings and this was not a big performance issue in R4. There were other issues and when we were handling those issues, this one also got fixed along the way. But in fact it was not really that important to fix.

[ForumsAdmin]

@egormsen
Your exception log looks similar to Joe's. I think they are both related.

[AbleMods]

I'm not sure I agree with the idea that store settings shouldn't be cached. There's no reason not to, assuming the cached data is not subject to rapid or frequent change.

NextOrderNumber is one of the few store settings than can (and does) change frequently on a high volume site. Perhaps there's a more cache-friendly place to store it than in the middle of 50 other settings that hardly ever change.

W've spent all this time and effort to build an API around speed and efficiency using a whole new design pattern. Seems silly to tap a 50-row table 10,000 times an hour when only 1 row will change in that same hour.

[ForumsAdmin]

NextOrderNumber is not a store setting that is cached anyway. NextOrderNumber is stored directly ac_Stores table.

[ForumsAdmin]

I'm not sure I agree with the idea that store settings shouldn't be cached.

We don't agree with it either but this is not the main concern right now. We first have to figure out if it actually is the caching of the store settings that is causing the issues above. If caching is not the cause to start with then having or not having the cache is pointless discussion.

[AbleMods]

Oh ok, I thought you were saying no more caching store settings, ever

Whew!

[ForumsAdmin]

One more thing can be done to get better error details. The actual exception trace is lost because exception is caught and rethrown in EntityWithTypedId.Save() method

Code: Select all

            try
            {
                saveMethod.Invoke(repo, new object[] { this });
            }
            catch (TargetInvocationException tiex)
            {
                if (tiex.InnerException != null) throw tiex.InnerException;
                throw;
            }

The above code if changed to the following will give us better exception stack trace

Code: Select all

          saveMethod.Invoke(repo, new object[] { this });

Joe - If you can make this change to your code it would be great for debugging. Your help is greatly appreciated. On our local systems, all our efforts to reproduce the bug have failed.

[ForumsAdmin]

To help us reproduce this please report
- IIS Version
- .NET version
- App Pool configurations
- AC Gold deployment mode (Web site or web application)

[AbleMods]

To help us reproduce this please report
- IIS Version
- .NET version
- App Pool configurations
- AC Gold deployment mode (Web site or web application)

IIS 7.5
ASP.Net 4.0 Integrated
Website Deployment

Updates have been deployed. Will update here after we've had some time to see how it goes.

[ForumsAdmin]

IIS 7.5
ASP.Net 4.0 Integrated
Website Deployment

This is one of the common configurations that we test. Wonder why we never saw something that has been reported by at least two users.

[acuser777]

Exact same problem. Working with AbleCommerce through support ticket.

[AbleMods]

This install is CLR 4.0.30319.1008 on Server 2008 R2

[egormsen]

Problems happened again this morning. Customers and our customer service reps both could not place orders. This time restarting app pool and restarting the website site did not work. Had to make a change that forced a recompile.

Our environment looks about the same as Joes
Windows Server 2008 R2
IIS 7.5
app pool is set as ASP.Net 4.0 Integrated 4.0.30319
Website Deployment

We do not have full source so I can not do your earlier suggestion. If there is something I can do to help narrow this problem down please let me know.

[ForumsAdmin]

Can you please share your full app.log file?

[egormsen]

Here it is