Injected log property is missing in services

Please attach an example application that reproduces the problem

Hi Grame, it's not so easy.

This issue is not always reproducable. It happen's from time to time.
In our environment we are getting this error approximately once a week (deploying one to two times the day).
It concerns only the log-property in the services. The log-properties in controllers are always there.

We are using around 30 services classes in our application. If the log property is missing, it seems
to be disappeared in all services classes.

In production or development environment?

in both of them (please see the 'environment' section above)

Well it is pretty hard to tell without a reproducible set of circumstances tbh

That's true. We will keep track of this.
Because some other people experienced similar problems, this ticket is meant as a 'collecting basin' for tracking this issue down.
There is a workaround for it (see above), so it's not very critical.

We've had the same problem on our production environment. We are using Tomcat 6 as our servlet container. After switching from the NIO connector to the normal HTTP connector, we've not encountered the problem anymore, but that might be because it just happens less often.

The work around for the log property did not help us, as we had other properties and closures injected by a plugin (JMS), which we also couldn't use.

Just for the record: I occasionally see this problem in both devel and production (WAR on tomcat) mode using 1.0.x SVN head. Restarting the app always fixes the problem.

From the mailinglist (Marc Palmer):

Myself and others have been periodically seeing error messages when starting apps or running tests, where the "log" property is not found on services.

I think I have nailed this.

Basically the dynamic logs are added by the core LoggingGrailsPlugin. If a plugin in your application supplies services or other artefacts that access their "log" property during plugin setup callbacks (doWithXXX etc), but the plugin does not explicitly load after the logging plugin, then this problem can happen.

The workaround is to make all plugins load and init after the logging plugin - but in future this needs to be done by default IMO - we should have some way to mandate a small set of internal plugins that execute first I think - or all "core" plugins are loaded before any application or user-installed ones.

Its a bit crappy to have to require all plugins to depend on and load after the logging plugin.

Maybe I haven't read the documentation well enough, but how does one depend on the loading of a particular plugin? In other words, could anybody give an example?

Thanks,
Ilja

implemented suggested fix. I have not been able to reproduce the problem, so verification of the fix would be appreciated

I am still having this problem with Grails 1.1.1

My services (found under grails-app/services) try to log in the afterPropertiesSet() Spring callback.

We are still observing this problem with Grails 1.0.5 on our production systems. I believe I have determined the true root cause, however, and I'll be posting with additional information shortly.

I have been able to trace this failure to a defect in Groovy when calling the MetaClassRegistry.removeMetaClass() method. The root cause is that calls to MetaClassRegistry.removeMetaClass() can cause unexpected classes to be effectively removed from the MetaClassRegistry. See GROOVY-3623 for more details.

This defect manifests itself when the DefaultGrailsPluginManager calls its doDynamicMethods() method at start up. Prior to calling each plugins' doWithDynamicMethods() method (e.g. injecting the log property in the LoggingGrailsPlugin), a call to MetaClassRegistry.removeMetaClass() is made for each of the common Java classes:

public void doDynamicMethods() {
      checkInitialised();
      // remove common meta classes just to be sure
      MetaClassRegistry registry = GroovySystem.getMetaClassRegistry();
      for (int i = 0; i < COMMON_CLASSES.length; i++) {
          Class commonClass = COMMON_CLASSES[i];
          registry.removeMetaClass(commonClass);
      }
      for (Iterator i = pluginList.iterator(); i.hasNext();) {
          GrailsPlugin plugin = (GrailsPlugin) i.next();
          plugin.doWithDynamicMethods(applicationContext);
      }
  }

Each call to MetaClassRegistry.removeMetaClass() carries the risk that one or more other MetaClass entries will become inaccessible. If this happens to one of the Grails Artefact beans, the MetaClass for those beans will not be updated with any dynamic methods added for their Class.

Here's what happens when the MissingPropertyException is thrown:

1. Grails application starts.
2. Spring beans are created for Grails artefacts. Metaclass es for those beans are automatically registered with the Groovy MetaClassRegistry.
3. DefaultGrailsPluginManager makes calls to MetaClassRegistry.removeMetaClass(), ends up removing the MetaClass entry for one of the beans (e.g. a Grails service, job, etc.) This is the true point of failure.
4. LoggingGrailsPlugin adds dynamic getLog method for each artefact Class. However, for the artefact Class that was accidentally removed in step 3, a new MetaClass is created and registered, different from the one referenced within the bean for that artefact. The new MetaClass is injected with getLog, the old one is not.
5. A reference to the bean's log property is made. The MetaClass for this bean has never been modified, so a MissingPropertyException is thrown.

The real solution to this problem is to incorporate a version of Groovy with this defect patched (patch just submitted.) To workaround this specific failure case, one could also modify the LoggingGrailsPlugin such that each artefact bean's MetaClass is injected with the getLog method, in addition to the Class. However, this would still leave you vulnerable to the other possible problems with dynamic method injection caused by GROOVY-3623 .

GROOVY-3623 has been fixed with v1.6.4. When Grails is updated to use Groovy 1.6.4, this issue will be resolved.

I'm still experiencing this problem with Grails 1.2-M3 (Groovy 1.6.4), but I think it's due to the Grails testing framework/documentation rather than GROOVY-3623. Extremely simple to reproduce:

class MyService {
    def myMethod() {
        log.info "this will throw a groovy.lang.MissingPropertyException"
    }
}

class MyServiceTests extends GrailsUnitTestCase {
    void testMyMethod() {
        def myService = new MyService();
        myService.myMethod();
    }
}

I guess the cause is fairly obvious as there is no proxy class generated for the service when called from the test case. I'm not sure how to solve the issue, any help would be much appreciated.

Ah, figured it out after stumbling upon a reference to mockLogging in the documentation. In case anyone else is having this issue, here's the fix:

class MyServiceTests extends GrailsUnitTestCase {
    def myService

    protected void setUp() {
        super.setUp()
        mockLogging(MyService.class, true)
        myService = new MyService()
    }

    void testMyMethod() {
        myService.myMethod();
    }
}

Bulk closing bunch of resolved issues