How do you tell if user maintenance is actually running?

[AbleMods]

My ac_Users table is enormous - far more than my web site statistics represent. I don't think user maintenance is cleaning up old anonymous accounts.

How do you tell if user maint. actually ran?

[WylieE]

Maintenance operations are logged in the app.log.

I see entries in my logfile, so I'm presuming it is running.

[jmestep]

Joe, I remember wondering the same about a site because the table had so many users. I just can't remember which one it was now.

[Logan Rhodehamel]

Maintenance operations are logged in the app.log.

This is correct - App_Data/app.log. And periodically it should report "User maintenance removed 124 expired user records" or something along those lines.

[AbleMods]

AHA! Thank you - forgot all about app.log.

Mine's showing that user maint. ran and it cleared x expired anonymous users.

Wonder what it means ".....disabled 3 expired merchant acounts."

[Logan Rhodehamel]

Wonder what it means ".....disabled 3 expired merchant acounts."

There are at least 3 accounts that are assigned to groups that have associated permissions, and those accounts have not been logged into for X months... maybe 6 or 12 depending on your policy.

There is a known bug where this message keeps getting logged each time maintenance runs even if the accounts are already disabled. It is corrected for the next release.

[AbleMods]

Ohhhhhh. Would that would explain my one of my backup login accounts was marked as "disabled" ?

I thought someone was trying to brute-force the login info

[Logan Rhodehamel]

No... requirement of PCI is that dormant admin accounts be expired. You can increase the timeout up to 24 months from our form, but I can't remember if 6 or 12 is the limit for PCI compliance.

[Logan Rhodehamel]

Shoot I was wrong. PCI DSS v1.2, sec 8.5.5 says: Remove/disable inactive user accounts at least every 90 days. This refers to non consumer (admin) accounts.

Just FYI.

[AbleMods]

Ok think I found my problem.

My ac_Users is showing no less than 734,000+ user records. So something wasn't quite right.

I checked my user maintenance settings and my anonymous days-to-save was set correctly. But I see my affiliate days-to-save was blank, i.e. forever. Since ALOT of my inbound traffic comes from affiliate-coded URLs in Google, this could explain the extraordinarily large user list. I've adjusted the value to 90 days.

I'll monitor the app.log and see if I catch a sudden huge cleansing of the users table

[Logan Rhodehamel]

You can force maintenance to occur if you restart the web application (e.g. modify the web.config file or reset it in IIS). Maintenance will occur on the first visit. I keep meaning to add a button in the admin so you can trigger it manually - that would probably come in handy here and there.

[AbleMods]

Hmmm.

I bounced IIS and it only cleared out another 5,000 or so anonymous users. Something still isn't right.

I see in my app log:

Code: Select all

INFO  2009-09-09 14:23:38,064   187ms Object                 a                  - Running maintenance routines
INFO  2009-09-09 15:18:01,173 3263296ms Object                 a                  - User maintenance cleared 5653 expired anonymous users, last active before 8/30/2009 6:23:38 PM
INFO  2009-09-09 15:18:01,189 3263312ms Object                 a                  - User maintenance disabled 3 expired merchant accounts.
INFO  2009-09-09 15:18:08,829 3270953ms Object                 a                  - Payment maintenance cleared 2 expired payments, completed before 9/4/2009 7:18:08 PM
INFO  2009-09-09 15:18:09,783 3271906ms Object                 a                  - Page view maintenance cleared 27110 expired records.
INFO  2009-09-09 15:18:10,048 3272171ms Object                 a                  - Maintenance routines complete
INFO  2009-09-09 16:26:24,923   140ms Object                 a                  - Running maintenance routines
INFO  2009-09-09 16:32:46,829 382046ms Object                 a                  - User maintenance cleared 648 expired anonymous users, last active before 8/30/2009 8:26:24 PM

Yet I look in my ac_users table and do a select * from ac_users where isanonymous = 1. It returned hundreds of thousands of records with lastactivity dates in 2008. Here's the result set from a top(10) *:

ac_users.jpg

What's the exact criteria for maintenance to purge an anonymous user? Something's getting missed in my store. My ac_Users table is well over 750,000 records now.

[Logan Rhodehamel]

For non-affiliate anonymous users:

SELECT UserId FROM ac_Users WHERE StoreId = @storeId AND IsAnonymous = 1 AND AffiliateId IS NULL AND ReferringAffiliateId IS NULL AND (LastActivityDate IS NULL OR LastActivityDate < @expireDate)

For affiliate anonymous users:

SELECT UserId FROM ac_Users WHERE StoreId = @storeId AND IsAnonymous = 1 AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) AND (LastActivityDate IS NULL OR LastActivityDate < @expireDate)

Does this help?

[AbleMods]

The first query returns 0 records:

Code: Select all

SELECT UserId FROM ac_Users 
WHERE StoreId = 1 AND IsAnonymous = 1 
AND AffiliateId IS NULL AND ReferringAffiliateId IS NULL 
AND (LastActivityDate IS NULL OR LastActivityDate < 'December 31, 2008')

That makes sense.

The second query returns 208,000+ records:

Code: Select all

SELECT UserId FROM ac_Users 
WHERE StoreId = 1 AND IsAnonymous = 1 
AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) 
AND (LastActivityDate IS NULL OR LastActivityDate <'December 31, 2008')

I don't get it. It's as if the affiliate anonymous users query isn't getting fired at all. Or....the @expiredate could be getting calculated wrong for that query. It's the only parameter that's dynamic. StoreId couldn't be wrong or all the queries in the storefront would fail.

Any ideas about @expiredate ?

[Logan Rhodehamel]

After you changed the anonymous user lifespan, when you view app.log, do you see any error about user maintenance failing? I am wondering if it's hitting a timeout because of the number of records.

[AbleMods]

I think you're right.

Look at this, noting the date/time of 648 deleted and the datetime of the failure of the next one. The reason it failed was because I rebooted the server at that time.

If we can assume the affiliate anon purge occurs immediately after the non-affiliate purge, these logs would seem to indicate that the affiliate anon purge was running from approx. 4:30pm until I rebooted at midnight. I'm guessing at this point, but it's indicative the separate-thread process for user maintenance may be running constantly, trying to clean up hundreds of thousands of records one-by-one-by-one.

But still, I only bounce that box every 30 days or so. You would think it would "catch up" eventually, no?

Maybe I need to run some sort of manual mass-delete on ac_users and thin it back down within reason for the maintenance routines to handle on their own again?

Code: Select all

INFO  2009-09-09 16:32:46,829 382046ms Object                 a                  - User maintenance cleared 648 expired anonymous users, last active before 8/30/2009 8:26:24 PM
WARN  2009-09-10 00:16:15,689 28190906ms Object                 a                  - Error running SQL: DELETE FROM ac_Users WHERE StoreId = @storeId AND UserId = @userId
System.Data.SqlClient.SqlException: A transport-level error has occurred when receiving results from the server. (provider: Shared Memory Provider, error: 0 - The pipe has been ended.)
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
   at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
   at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)
   at System.Data.SqlClient.TdsParserStateObject.ReadPacket(Int32 bytesExpected)
   at System.Data.SqlClient.TdsParserStateObject.ReadBuffer()
   at System.Data.SqlClient.TdsParserStateObject.ReadByte()
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(DbAsyncResult result, String methodName, Boolean sendToPipe)
   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
   at Microsoft.Practices.EnterpriseLibrary.Data.Database.DoExecuteNonQuery(DbCommand command)
   at Microsoft.Practices.EnterpriseLibrary.Data.Database.ExecuteNonQuery(DbCommand command)
   at CommerceBuilder.Data.Database.ExecuteNonQuery(DbCommand command)

[Logan Rhodehamel]

I'm guessing at this point, but it's indicative the separate-thread process for user maintenance may be running constantly, trying to clean up hundreds of thousands of records one-by-one-by-one.

It does this to avoid SQL timeouts and also because there is related data that may not be enabled for cascade delete.

At an off peak time, back up your database then try this:

Code: Select all

DELETE FROM ac_Baskets WHERE UserId = IN (SELECT UserId FROM ac_Users 
WHERE StoreId = 1 AND IsAnonymous = 1 
AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) 
AND (LastActivityDate IS NULL OR LastActivityDate <'December 31, 2008'))

DELETE FROM ac_Wishlist WHERE UserId = IN (SELECT UserId FROM ac_Users 
WHERE StoreId = 1 AND IsAnonymous = 1 
AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) 
AND (LastActivityDate IS NULL OR LastActivityDate <'December 31, 2008'))

DELETE FROM ac_Users 
WHERE StoreId = 1 AND IsAnonymous = 1 
AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) 
AND (LastActivityDate IS NULL OR LastActivityDate <'December 31, 2008')

I have registered a bug to better deal with your scenario. We should either institute a limit on the number of records processed each run, or consider using a stored procedure to better deal with large recordsets.

[AbleMods]

Done. ac_Users is down to a clean-and-tidy 210,290 records now. Thanks so much for your tireless efforts Logan. Your depth and variety of knowledge never ceases to amaze me.

(27816 row(s) affected)

(96 row(s) affected)

(271180 row(s) affected)

Had to modify the code slightly for SQL 2005 Express...here's the final T-SQL commands.

Code: Select all

DELETE FROM ac_Baskets 
WHERE UserId IN (SELECT UserId FROM ac_Users WHERE StoreId = 1 AND IsAnonymous = 1 
AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) 
AND (LastActivityDate IS NULL OR LastActivityDate <'June 30, 2009'))

DELETE FROM ac_Wishlists
WHERE UserId IN (SELECT UserId FROM ac_Users WHERE StoreId = 1 AND IsAnonymous = 1 
AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) 
AND (LastActivityDate IS NULL OR LastActivityDate <'June 30, 2009'))

DELETE FROM ac_Users 
WHERE StoreId = 1 AND IsAnonymous = 1 
AND (AffiliateId IS NOT NULL OR ReferringAffiliateId IS NOT NULL) 
AND (LastActivityDate IS NULL OR LastActivityDate <'June 30, 2009')

[jmestep]

I checked user tables on some of our databases and they all seem to be OK- I thought I had seen one that had a lot of users, but might be remembering wrong.