2

Closed

Contrib.Cache is not working on Azure Web Site

description

This is specific to AWS, not Azure VM or Azure Web Role.

Nothing is cached, here is the log I obtain on a very reduced site using tip version (not last NH change).
My cache is set to 3600 and there are no zeros in the path I am testing, but the \nakedcart2 request.
I set log4net to trace for contrib.cache, after adding some more parameters in logs to display the various keys for insert and get from cache.

I get a home page /, which gets by ajax a /nakedcontent view -> nothing get inserted in cache
I get another page /produits/test-product which gets an ajax non cachable /nakedcart2, the page is not inserted, the nakedcart2 is correctly interpreted as non cachable (only thing working)
2013-05-03 09:44:37,125 [53] Contrib.Cache.Filters.OutputCacheFilter - Request on: /
2013-05-03 09:44:37,406 [56] Contrib.Cache.Filters.OutputCacheFilter - Request on: /nakedcontact
2013-05-03 09:44:38,234 [56] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/nakedcontact;theme=cloudissime;action=nakedcontact;
2013-05-03 09:44:38,547 [53] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/;theme=cloudissime;action=display;id=12;
2013-05-03 09:45:13,826 [56] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/nakedcontact;theme=cloudissime;action=nakedcontact; - 3600
2013-05-03 09:45:23,201 [53] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/;theme=cloudissime;action=display;id=12; - 3600
2013-05-03 09:45:48,059 [47] Contrib.Cache.Filters.OutputCacheFilter - Request on: /
2013-05-03 09:45:48,512 [47] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/;theme=cloudissime;action=display;id=12;
2013-05-03 09:46:26,182 [47] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/;theme=cloudissime;action=display;id=12; - 3600
2013-05-03 09:46:43,118 [51] Contrib.Cache.Filters.OutputCacheFilter - Request on: /produits/test-product
2013-05-03 09:46:43,634 [51] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/produits/test-product;theme=cloudissime;action=display;id=48;
2013-05-03 09:47:42,225 [51] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/produits/test-product;theme=cloudissime;action=display;id=48; - 3600
2013-05-03 09:47:53,802 [61] Contrib.Cache.Filters.OutputCacheFilter - Request ignored based on OutputCache attribute-NakedCart2-ShoppingCart2
2013-05-03 09:47:53,865 [51] Contrib.Cache.Filters.OutputCacheFilter - Request on: /
2013-05-03 09:47:54,318 [51] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/;theme=cloudissime;action=display;id=12;
2013-05-03 09:48:52,799 [51] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/;theme=cloudissime;action=display;id=12; - 3600
2013-05-03 09:49:30,671 [69] Contrib.Cache.Filters.OutputCacheFilter - Request on: /nakedcontact
2013-05-03 09:49:31,265 [69] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/nakedcontact;theme=cloudissime;action=nakedcontact;
2013-05-03 09:49:37,546 [69] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/nakedcontact;theme=cloudissime;action=nakedcontact; - 3600
2013-05-03 09:50:12,481 [38] Contrib.Cache.Filters.OutputCacheFilter - Request on: /produits/test-product
2013-05-03 09:50:12,934 [38] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/produits/test-product;theme=cloudissime;action=display;id=48;
2013-05-03 09:51:09,385 [38] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/produits/test-product;theme=cloudissime;action=display;id=48; - 3600
2013-05-03 09:51:20,415 [68] Contrib.Cache.Filters.OutputCacheFilter - Request ignored based on OutputCache attribute-NakedCart2-ShoppingCart2
2013-05-03 09:51:20,462 [51] Contrib.Cache.Filters.OutputCacheFilter - Request on: /
2013-05-03 09:51:20,947 [51] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/;theme=cloudissime;action=display;id=12;
A repro is to install Orchard and set log4net to trace, then add some pages and look for result in logs
Closed May 14, 2013 at 8:12 PM by sebastienros
Closing but watching for reasons it could happen, so not really closed

comments

CSADNT wrote May 3, 2013 at 4:15 PM

Just to be comprehensive, the same in local W8, IISExpress
2013-05-03 18:04:24,985 [14] Contrib.Cache.Filters.OutputCacheFilter - Request on: /
2013-05-03 18:04:26,223 [14] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/;theme=cloudissime;action=display;id=12;
2013-05-03 18:06:41,395 [14] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/;theme=cloudissime;action=display;id=12; - 3600
2013-05-03 18:06:43,250 [6] Contrib.Cache.Filters.OutputCacheFilter - Request on: /nakedcontact
2013-05-03 18:06:43,259 [6] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/nakedcontact;theme=cloudissime;action=nakedcontact;
2013-05-03 18:06:45,364 [6] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/nakedcontact;theme=cloudissime;action=nakedcontact; - 3600
2013-05-03 18:08:49,074 [29] Contrib.Cache.Filters.OutputCacheFilter - Request on: /produits/serveurs-windows
2013-05-03 18:08:49,079 [29] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/produits/serveurs-windows;theme=cloudissime;action=display;id=19;
2013-05-03 18:09:36,514 [25] Contrib.Cache.Filters.OutputCacheFilter - Request on: /nakedcontact
2013-05-03 18:09:36,520 [25] Contrib.Cache.Filters.OutputCacheFilter - Cache item found, expires on 03/05/2013 17:06:43
2013-05-03 18:09:41,869 [22] Contrib.Cache.Filters.OutputCacheFilter - Request on: /produits/serveurs-windows
2013-05-03 18:09:41,875 [22] Contrib.Cache.Filters.OutputCacheFilter - Cached version not found - tenant=Default;url=/produits/serveurs-windows;theme=cloudissime;action=display;id=19;
2013-05-03 18:10:55,793 [22] Contrib.Cache.Filters.OutputCacheFilter - Cache item added: tenant=Default;url=/produits/serveurs-windows;theme=cloudissime;action=display;id=19; - 3600
2013-05-03 18:10:57,069 [24] Contrib.Cache.Filters.OutputCacheFilter - Request ignored based on OutputCache attribute-NakedCart2-ShoppingCart2
2013-05-03 18:11:57,735 [29] Contrib.Cache.Filters.OutputCacheFilter - Request on: /produits/serveurs-windows
2013-05-03 18:11:57,741 [29] Contrib.Cache.Filters.OutputCacheFilter - Cache item found, expires on 03/05/2013 17:09:41
2013-05-03 18:11:58,791 [25] Contrib.Cache.Filters.OutputCacheFilter - Request ignored based on OutputCache attribute-NakedCart2-ShoppingCart2

CSADNT wrote May 3, 2013 at 5:35 PM

last from AWS: monitor is not totally shutdown by hostcomponents.config ?????
I double chcked my hostcomponents.config, it should disable monitoring, but here is the trace, do note thta part of the monitoring is suppressed but from a point it restart
2013-05-03 16:56:53,630 [43] Orchard.Environment.Extensions.ExtensionLoaderCoordinator - Executing list of operations needed for loading extensions...
2013-05-03 16:56:53,646 [43] Orchard.FileSystems.Dependencies.DefaultExtensionDependenciesManager - Storing module dependency file.
2013-05-03 16:56:53,661 [43] Orchard.FileSystems.Dependencies.DefaultExtensionDependenciesManager - Existing document is identical to new one. Skipping save.
2013-05-03 16:56:53,661 [43] Orchard.FileSystems.Dependencies.DefaultExtensionDependenciesManager - Done storing module dependency file.
2013-05-03 16:56:53,677 [43] Orchard.Environment.Extensions.ExtensionLoaderCoordinator - Done loading extensions...
2013-05-03 16:56:53,692 [43] Orchard.Environment.DefaultOrchardHost - Disposing active shell contexts
2013-05-03 16:56:53,692 [43] Orchard.Environment.DefaultOrchardHost - Start creation of shells
2013-05-03 16:56:53,692 [43] Orchard.Environment.DefaultOrchardHost - Creating shell context for tenant Default
2013-05-03 16:56:53,708 [43] Orchard.Environment.ShellBuilders.ShellContextFactory - Creating shell context for tenant Default
2013-05-03 16:56:53,708 [43] Orchard.Environment.ShellBuilders.CompositionStrategy - Composing blueprint
2013-05-03 16:56:53,724 [43] Orchard.Environment.Extensions.ExtensionManager - Loading features
2013-05-03 16:56:53,739 [22] Orchard.Environment.Extensions.Loaders.PrecompiledExtensionLoader - Start loading pre-compiled extension "jQuery"
2013-05-03 16:56:53,739 [43] Orchard.Environment.Extensions.Loaders.PrecompiledExtensionLoader - Start loading pre-compiled extension "Publish Later"
2013-05-03 16:56:53,755 [22] Orchard.Environment.Extensions.Loaders.PrecompiledExtensionLoader - Done loading pre-compiled extension "jQuery": assembly name="Orchard.jQuery, Version=1.6.0.0, Culture=neutral, PublicKeyToken=null"
2013-05-03 16:56:53,755 [43] Orchard.Environment.Extensions.Loaders.PrecompiledExtensionLoader - Done loading pre-compiled extension "Publish Later": assembly name="Orchard.PublishLater, Version=1.6.0.0, Culture=neutral, PublicKeyToken=null"
2013-05-03 16:56:53,755 [22] Orchard.Environment.Extensions.Loaders.PrecompiledExtensionLoader - Start loading pre-compiled extension "Media"
2013-05-03 16:56:53,755 [39] Orchard.Environment.Extensions.Loaders.PrecompiledExtensionLoader - Monitoring virtual path "~/Modules/Orchard.jQuery/bin/Orchard.jQuery.dll"

CSADNT wrote May 5, 2013 at 6:47 PM

I give up with Orchard on AWS, dommage it was a very interesting offer.

sebastienros wrote May 9, 2013 at 6:12 PM

I don't think this is an issue with the cache
I have been seeing issues like this recently on my website, like something has changed in azure, and now the files get monitored, or the monitoring is really slow. Taking downs my website sometimes. It has worked just fine for a year.

CSADNT wrote May 9, 2013 at 7:40 PM

This is exactly what I have experienced: after a difficult start certainly due to my inexperience on orchard, it has been working ok, but in lats 10 days nothing was logical.
Concerning the cache, the trace shows clearly its not working, I migrated all the code on an Azure VM and it works perfectly.
I was also suspecting the Western Europe AWS to be not as uptodate as the US sites ?
Here in France, nobody in my MS contact knows about this ?

sebastienros wrote May 9, 2013 at 7:59 PM

I assume all data centers are updated at the same time.
I am investigating right now.

CSADNT wrote May 9, 2013 at 8:24 PM

Thanks. Concerning the data centers being utpdated all on same time, it looks crazy ? Are you sure ?

jsiegmund wrote May 11, 2013 at 2:11 PM

Azure datacenters are not updated simultaneously, there are update waves which roll-out sequentially. Would be pretty astonishing to get so many machines to update at the same time without downtime ;)

I've been trying to get Orchard to work on AWS today, but it's harder then I expected. I've been able to get it up and running, but performance is very sluggish and it keeps running out of CPU time. It also won't save any changes I make, it looks like the application pool is recycled on every request or something. Pages just don't get updated at all.

CSADNT wrote May 11, 2013 at 2:49 PM

Glad to see I am not the only, thanks.
I think Sebastien is checking this.
Have you used the last 1.x, he has changed hostcomponents.config to be sure to avoid file monitoring which seems to be part of the slow running and recycling ???
For AWS quite all fals has to be set on disabled....but I have no time to test again.

sebastienros wrote May 11, 2013 at 3:05 PM

I have fixed the issue on one of the websites, it had been set to a scale of 2, and I think the nodes where restarting each others by writing on file which the other one was watching, and so on.

In 1.x I have added a lot more preconfigured sections in HostComponenets.config for you to define what components should monitor files or not. You could even put all values to False on production and it would be fine. Memory consumption also goes down by 10Mb on a vanilla website (20%). You might need to restart the website if you install a new module or update a shape, but it production it's worth it.

If you guys want to send me your website or even better give me an access to the AWS website itself (even a staging one) I would be happy to see what is wrong.

There is still this scaling issue I have to deal with.

jsiegmund wrote May 11, 2013 at 5:32 PM

I was running in Shared mode with an instance count of 1. I published using webmatrix and the publish profile I downloaded. Settings / pages I change are not saved, entire site seems to be in read-only mode.

I'm running the 1.6.1. build, downloaded today. What changes should I make? I noticed memory usage is pretty high, around 280MB. And as said; CPU usage is capped by Azure.

AWS: http://repsaj.azurewebsites.net/
Normal provider: http://www.repsaj.nl

The normal one doesn't perform that well either, that's why I was looking at Azure to switch. I've got a premium MSDN subscription which gives me free resources.

sebastienros wrote May 11, 2013 at 8:19 PM

@jsiegmund

If you are using the Source Code then run a "build Precompiled" command and publish the result. You can also add the Contrib.Cache project to the solution before you do that.

If you have a MSDN subscription then you can have a Medium reserved instance for free and host multiple Orchard websites on it for free.

jsiegmund wrote May 13, 2013 at 6:02 AM

Hi Sebastien,

I already had Contrib.Cache added. The build precompiled I'll try tonight or tommornight.

As for the MSDN subscription: I know, but I only need to host one and it's a simple one; so I was kinda hoping I could do with less.

sebastienros wrote May 13, 2013 at 4:36 PM

Please keep me up to date with your progress then. Ping me directly if you need assistance.

CSADNT wrote May 15, 2013 at 4:04 PM

Working on an Azure Web Role version of Orchard, I noticed that HostComponent.Config for Azure should be updated, shoudldn't it ?