U4-4922 - Getting loads of errors in the event log "FindAndExecuteExtensionMethod"

Created by Gordon Pretorius 14 May 2014, 19:53:46 Updated by Stephan 15 Mar 2016, 15:53:53

Relates to: U4-4931

Relates to: U4-6438

We have deployed a high end Umbraco 7 website. For the past week everything has been running fine, until earlier today we are getting loads of the exceptions below being written to the event log, which in turn is causing the service to crash and throw 503 errors. It also causes loads of OutOfMemory exceptions (It's a server with 8GB Mem)

Any idea what could cause this? There has not been any code changes to it's strange

Any help is much appreciated! I have attached the log file for reference.

ERROR Umbraco.Core.Dynamics.DynamicInstanceHelper - [Thread 23] An error occurred finding an executing an extension method for type Umbraco.Web.Models.DynamicPublishedContentTypes searched for extension methods were Umbraco.Web.Models.DynamicPublishedContent, System.MissingMethodException: Attempted to access a missing method. at Umbraco.Core.Dynamics.DynamicInstanceHelper.FindAndExecuteExtensionMethod[T](T thisObject, Object[] args, String name, IEnumerable1 findMethodsOnTypes) at Umbraco.Core.Dynamics.DynamicInstanceHelper.TryInvokeMember[T](T thisObject, InvokeMemberBinder binder, Object[] args, IEnumerable1 findExtensionMethodsOnTypes)

2 Attachments

Download UmbracoTraceLog.txt

Download UmbracoTraceLog.txt

Comments

Gordon Pretorius 19 May 2014, 10:20:41

It would be VERY helpful if the exception could output the name of the method it was trying to find. This could at least provide some steer as to the cause of the issue. Especially as it's only happening only a live site with 1000 requests a minute, so it's nearly impossible to determine on what page it's occurring.

Thanks

Gordon


Sebastiaan Janssen 19 May 2014, 14:06:01

So this seems to be happening from one of your views where you're using CurrentPage.Something or Model.Content.Something. It seems like the property ("Something" in my example) can't be found which is why it's throwing this error. This could very well have something to do with the fact that your editors are not filling in all of the fields. Dislaimer: I'm not very familiar with this part of the codebase, so I have no idea if I'm saying something stupid here!

The quickest way to debug could be to take a copy of the live database and restore that locally and use it against your local version of the site. Start with an empty log file and hit a few pages in your site, after accessing each page, look in the log to see if this error comes up. Once it does, check the template for that page and start removing things to see if that fixes it. If that helps narrowing it down, update this issue to see what can be done about it.

My initial suggestion would be to cache (parts of) the page in question so it only gets this exception once and it doesn't keep happening.


Gordon Pretorius 19 May 2014, 14:19:43

Thanks for the feedback Sebastiaan. This is where things get a bit weird. We created a staging environment based on the LIVE code, and created a duplicate of the LIVE database, and to our absolute amazement, no errors. It's only on the LIVE site...

Do you know where and how Umbraco caches data? And when does it read from the umbraco.config? (I noticed this is a publish of the full site)

Thanks again.

G


Sebastiaan Janssen 19 May 2014, 14:35:15

Do you have the posibility to switch the live and staging server so that you can check if the problem is environment specific? It sounds like maybe there's robots hitting your site on unexpected (maybe old) URLs and that might be the cause of the problem. The other thing might be that if you have for example a template called Contact but your contact page is at /Contact-Us then you can still go to mysite.com/Contact (or mysite.com/altTemplate=Contact), which then would render the home page with the alternative template "Contact" (this is just an example, but any of your templates could be used in this way). So maybe a robot/spider is hitting that url and the homepage doesn't have a lot of the properties on it that the "Contact" template is asking for. I'm thinking this especially because you said it started happening after the site was live for a while.

Caching is not something I can explain in a few lines of text. Umbraco only loads the umbraco.config in memory after an app pool recycle, from there on out when something gets published it's sent to memory and then umbraco.config seperately.


Gordon Pretorius 20 May 2014, 10:57:53

Thanks for this Sebastiaan. It makes sense what you are saying which would explain the errors, and the environment differences. Would it be possible to output the method name in the exception?

Regards

G


Stephan 22 May 2014, 16:33:16

The error comes from DynamicInstanceHelper.TryInvokeMember() which is used by DynamicPublishedContent.TryInvokeMember() whenever a call such as content.DoSomething() is issued and the runtime binder has to look for that method. TryInvokeMember() will look for a property, then a static or instance method, then an extension method, then fail.

When failing, it reports that the extension method was not found by writing to the log, yet it does not throw, and a DynamicNull is returned.

So yes it can potentially flood the log.

No idea why it would work in one environment and not the other.

Have pushed 1cf40aca07ee5f48baac2b2f013f5e6482bfa243 into 7.1.4 that makes the error message more verbose, detailing the type & method.


Gordon Pretorius 23 May 2014, 16:23:40

Upon further investigation, I suspect issue U4-4931 is the cuase of the application locks.


Stephan 28 Jun 2014, 13:09:12

Have you been able to use 7.1.4 and figure out which extension method could not be found?


Gordon Pretorius 23 Jul 2014, 16:03:17

Hi Stephan,

Sorry, everything has finally settled. Currently no, the extension method is not outputting as hoped (we are currently on 7.1.4)

I have included today's log file as a sample. Let me know if any insight.

Thanks again

Gordon


Stephan 13 Aug 2014, 10:51:31

Are you sure you properly upgraded to 7.1.4? The error messages in the log you uploaded are pre-7.1.4, in 7.1.4 it should now tell you which extension method is missing, etc.


Stephan 15 Mar 2016, 15:53:26

Suspecting U4-6438 is fixing it - because of "''This is where things get a bit weird. We created a staging environment based on the LIVE code, and created a duplicate of the LIVE database, and to our absolute amazement, no errors. It's only on the LIVE site...''" - which usually indicates some assembly loading errors.

U4-6438 deals with those errors in a much better way, so that we stop flooding the log.

Closing this issue as fixed.


Priority: Normal

Type: Bug

State: Fixed

Assignee:

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions:

Due in version: 7.4.2

Sprint: Sprint 11

Story Points:

Cycle: