Figuring out why JSF getters are called when I don't expect them to be called

Question

I'm working with jsf 2 and I'm getting some behaviour which I find hard to explain or understand.

I have several independent h:forms.

one of which looks like this:

<h:form>
    <h:commandButton value="#{text.General_Wipe_Now}" action="#{bean.doThate}" >
        <f:ajax execute="@form" render="@form" />
    </h:commandButton>
    <h:selectBooleanCheckbox value="#{bean.ignoreErrors}">Ignore Errors</h:selectBooleanCheckbox>
</h:form>

My question/issue is that whenever I press the aformentioned button, I see other, unrelated, bean member getters (that are parts of other forms) being called. (Through logging)

There is no business logic in any of the getters but I would like to understand the reason for this. Through printing stacktrace I made sure that JSF is indeed the one calling them.

How would you suggest I follow JSF to understand why they are being called? What could be the reason?

Thanks! Ben.

UPDATE

Here is the stacktrace as printed by one of the getters that are running and are not supposed to . As discussed in the comments, it will be extremely complex to include in this question all of the details that are related so I would rather get help with the tools to find the answer myself.

java.lang.Exception
    at com.aCompanyName.applicationName.beans.aBean.getSomethingFromBean(CurrentDevice.java:382)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at javax.el.BeanELResolver.getValue(BeanELResolver.java:302)
    at javax.el.CompositeELResolver.getValue(CompositeELResolver.java:175)
    at org.apache.myfaces.el.unified.resolver.FacesCompositeELResolver.getValue(FacesCompositeELResolver.java:142)
    at com.sun.el.parser.AstValue.getValue(AstValue.java:116)
    at com.sun.el.parser.AstValue.getValue(AstValue.java:163)
    at com.sun.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:219)
    at org.apache.myfaces.view.facelets.el.TagValueExpression.getValue(TagValueExpression.java:85)
    at org.apache.myfaces.view.facelets.component.UIRepeat.getValue(UIRepeat.java:248)
    at org.apache.myfaces.view.facelets.component.UIRepeat.getDataModel(UIRepeat.java:211)
    at org.apache.myfaces.view.facelets.component.UIRepeat._validateAttributes(UIRepeat.java:530)
    at org.apache.myfaces.view.facelets.component.UIRepeat.visitTree(UIRepeat.java:763)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:797)
    at javax.faces.component.UIComponentBase.visitTree(UIComponentBase.java:992)
    at org.apache.myfaces.view.facelets.tag.ui.DebugPhaseListener._doTreeVisit(DebugPhaseListener.java:310)
    at org.apache.myfaces.view.facelets.tag.ui.DebugPhaseListener.afterPhase(DebugPhaseListener.java:286)
    at org.apache.myfaces.lifecycle.PhaseListenerManager.informPhaseListenersAfter(PhaseListenerManager.java:111)
    at org.apache.myfaces.lifecycle.LifecycleImpl.executePhase(LifecycleImpl.java:185)
    at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:189)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    at org.apache.openejb.tomcat.catalina.OpenEJBValve.invoke(OpenEJBValve.java:45)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:852)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
    at java.lang.Thread.run(Thread.java:662)

UPDATE 2

Working on making a SSCCE, will update once I have one.

UPDATE 3

The problem seems to occur with <ui:repeat> value attribute. This is a SSCCE code that exemplifies the problem:

<h:body>
    <ui:repeat var="str" value="#{admin.SList}">
        STRING: #{str}
    </ui:repeat>

    <h:form>
        <h:commandButton value="pressie" action="#{admin.doThat}">
            <f:ajax execute="@form"/>
        </h:commandButton>
    </h:form>
</h:body>

The Bean Code:

@PostConstruct
public void init()
{
    slist.add("Testing");
    slist.add("This");
    slist.add("Thing");
}

private List<String> slist = new ArrayList<String>();

public List<String> getSList(){
    logger.trace("Getting LIST");
    return slist;
}

public void doThat(){
    logger.trace("DoThat Was Run");
}

When pressing the button, this is output to the log:

2011-08-16 16:55:55,853 TRACE [http-80-2] (AdminBean.java:80) - Getting LIST
2011-08-16 16:55:55,865 TRACE [http-80-2] (AdminBean.java:85) - DoThat Was Run

Why is getting list run? Is it not redundant?

Answer 1

I don't use MyFaces, so I won't go in its specifics. But for what is worth, on Mojarra the getter is also called for <ui:repeat>. However, the stack is imo more clear as to what is happening. Here's the Thread#dumpStack() until FacesServlet#service():

java.lang.Exception: Stack trace
    at java.lang.Thread.dumpStack(Thread.java:1249)
    at mypackage.Bean.getList(Bean.java:21)
    at sun.reflect.GeneratedMethodAccessor51.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at javax.el.BeanELResolver.getValue(BeanELResolver.java:302)
    at com.sun.faces.el.DemuxCompositeELResolver._getValue(DemuxCompositeELResolver.java:176)
    at com.sun.faces.el.DemuxCompositeELResolver.getValue(DemuxCompositeELResolver.java:203)
    at com.sun.el.parser.AstValue.getValue(AstValue.java:116)
    at com.sun.el.parser.AstValue.getValue(AstValue.java:163)
    at com.sun.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:219)
    at com.sun.faces.facelets.el.TagValueExpression.getValue(TagValueExpression.java:109)
    at com.sun.faces.facelets.component.UIRepeat.getValue(UIRepeat.java:272)
    at com.sun.faces.facelets.component.UIRepeat.getDataModel(UIRepeat.java:248)
    at com.sun.faces.facelets.component.UIRepeat.setIndex(UIRepeat.java:442)
    at com.sun.faces.facelets.component.UIRepeat.doVisitChildren(UIRepeat.java:661)
    at com.sun.faces.facelets.component.UIRepeat.visitTree(UIRepeat.java:619)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1600)
    at javax.faces.component.UIComponent.visitTree(UIComponent.java:1600)
    at com.sun.faces.application.view.StateManagementStrategyImpl.restoreView(StateManagementStrategyImpl.java:240)
    at com.sun.faces.application.StateManagerImpl.restoreView(StateManagerImpl.java:188)
    at com.sun.faces.application.view.ViewHandlingStrategy.restoreView(ViewHandlingStrategy.java:123)
    at com.sun.faces.application.view.FaceletViewHandlingStrategy.restoreView(FaceletViewHandlingStrategy.java:452)
    at com.sun.faces.application.view.MultiViewHandler.restoreView(MultiViewHandler.java:148)
    at javax.faces.application.ViewHandlerWrapper.restoreView(ViewHandlerWrapper.java:303)
    at com.sun.faces.lifecycle.RestoreViewPhase.execute(RestoreViewPhase.java:189)
    at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
    at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:113)
    at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:409)
    // Remnant omitted for brevity.

It is thus happening during the restore view phase when the state management needs to visit the entire component tree. The UIRepeat in turn needs to set the row index when its children are to be visited.

According to the UIRepeat#doVisitChildren() source the row index is set to -1. The final goal is to just visit its children in the tree, not to iterate over the model value nor to render anything. It just needs the DataModel in order to be able to set the row index. The value of the datamodel is the list for which you're seeing the getter being invoked. If anything is fine, this getter should be invoked only once during restore view phase. However, if it was invoked during for example render response phase as well, then you may be worrying about this because it would have been completely unnecessary.