XForms logging
Sometimes, an error message or stack trace in the Orbeon Forms log file provides enough information to a developer to figure out what went wrong, but not always. In such cases, you can turn to the XForms engine logging facility. To enable it, make sure you uncomment the following logging
<Logger>
(Log4j 2.x) or <Category>
(Log4j 1.x):Log4j 2.x (
WEB-INF/resources/config/log4j2.xml
):<Logger name="org.orbeon.oxf.xforms.processor.XFormsServer" level="debug"/>
Log4j 1.x (
WEB-INF/resources/config/log4j.xml
):<category name="org.orbeon.oxf.xforms.processor.XFormsServer">
<priority value="debug"/>
</category>
Note: You must restart your Servlet container for those changes to be taken into account.
Two properties in
WEB-INF/resources/config/properties-local.xml
control exactly what is logged by the XForms engine: <property as="xs:NMTOKENS" name="oxf.xforms.logging.debug">
document
model
submission
control
event
action
analysis
server
html
process
</property>
<property as="xs:NMTOKENS" name="oxf.xforms.logging.error">
submission-error-body
</property>
oxf.xforms.logging.debug
controls what is logged at debug level:- Related to a particular XForms document:
model
- activity related to
xf:model
, including instance loads, validation, and binds
submission
- timing activity related to
xf:submission
submission-details
- detail activity related to
xf:submission
- requires
submission
to be present as well
control
- activity related to controls
event
- activity related to events dispatching and propagation
action
- activity related to XForms actions
document
- other activity related to an XForms document
- this includes the output of the
<xf:message>
action with levelxxf:log-debug
process
- Not related to a particular XForms document:
analysis
- activity related to the static analysis of an XForms document
server
- activity related to handling Ajax requests
html
- activity related to converting XForms to HTML
resources
- activity related to handling XForms CSS and JavaScript resources
state
- activity related to state handling
resolver
- activity related to the URI resolver
utils
- miscellaneous activity
cache
- [SINCE Orbeon Forms 4.6]
- activity of the static state cache during XForms initialization
- Data:
html-static-state
- requires
html
- outputs the static state input
analysis-xbl-tree
- requires
analysis
- outputs the detail of the XBL shadow trees computed
submission-body
- requires
submission
ANDsubmission-details
- outputs the detail of submission request/response bodies
model-serialized-instance
- requires
model
- outputs the full instances serialized into the dynamic state after an Ajax request completes
server-body
- requires
server
- outputs the full Ajax request and response bodies
oxf.xforms.logging.error
controls what is logged at error level:submission-error-body
- Whether to attempt to output a submission response body when a submission error occurs
- This is enabled by default, but you can turn it off, e.g. for data sensitivity reasons
- Binary bodies are not logged, but the logger mentions that the type is a binary type
- When the response body is NOT logged and is used for
replace="instance|all"
, streaming is taking place. However when the response body IS logged, streaming does not take place:- The body is read in memory
- The body is logged
- Then the rest of the submission proceeds
server-body
- output the Ajax request in case of error occurring while processing the request
During XForms development, you might want to enable a more aggressive debug configuration.
- 1.Change your Log4j2 or Log4j configuration. In your
WEB-INF/resources/config
, check if you have a file namedlog4j2.xml
orlog4j.xml
:- If you have a file named
log4j2.xml
(with2
in the file name), inside the element<Loggers>
, add:<Logger name="org.orbeon.oxf.xforms.processor.XFormsServer" level="debug"/><Logger name="org.orbeon.oxf.processor.DebugProcessor" level="debug"/><Logger name="org.orbeon.relational" level="debug"/><Logger name="org.orbeon.auth" level="debug"/><Logger name="org.orbeon.lifecycle" level="debug"/> - If you have a file named
log4j.xml
(without2
in the file name), uncomment the following:<category name="org.orbeon.oxf.xforms.processor.XFormsServer"><priority value="debug"/></category>
- 2.Configure the
oxf.xforms.logging.debug
property in yourconfig/properties-local.xml
. You can choose precisely what the XForms engine logs. The following is the most comprehensive configuration. It will log almost everything. In most cases, this is a good configuration during development, and while troubleshooting issues in staging:<property as="xs:NMTOKENS" name="oxf.xforms.logging.debug">documentmodelsubmissioncontroleventactionanalysisserverserver-bodyhtmlprocesssubmission-detailssubmission-body</property>
In production, you probably don't want any debug information coming out to your logs. So set this in
log4j.xml
:<category name="org.orbeon.oxf.xforms.processor.XFormsServer">
<priority value="info"/>
</category>
Alternatively, remove or comment-out the lines above. When this is done, the
oxf.xforms.logging.debug
property is no longer used, so it does not matter what it contains. However, the oxf.xforms.logging.error
is still relevant. Configure it appropriately, depending on whether you want to see submission responses bodies logged or not.If you only want to see submission timings, in your
log4j.xml
use:<category name="org.orbeon.oxf.xforms.processor.XFormsServer">
<priority value="debug"/>
</category>
And in your
properties-local.xml
:<property as="xs:NMTOKENS" name="oxf.xforms.logging.debug">
submission
</property>
The following shows a sample XForms logging session:
XForms server - start handling external events
XForms server - start handling external event {target id: "age-input-control", event name: "xxforms-value-change-with-focus-change"}
setvalue - setting instance value {value: "36", changed: "true", instance: "instance"}
event - start dispatching {name: "xxforms-value-changed", id: "instance"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xforms-recalculate", id: "main-model"}
model - start performing recalculate {model id: "main-model"}
setvalue - setting instance value {value: "A", changed: "false", instance: "instance"}
setvalue - setting instance value {value: "A", changed: "false", instance: "countries-instance"}
setvalue - setting instance value {value: "", changed: "false", instance: "country-details-instance"}
model - end performing recalculate {time (ms): "9"}
event - end dispatching {time (ms): "9"}
event - start dispatching {name: "xforms-revalidate", id: "main-model"}
model - start performing revalidate {model id: "main-model"}
event - start dispatching {name: "xxforms-invalid", id: "instance"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xxforms-valid", id: "resources-instance"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xxforms-valid", id: "flavors-instance"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xxforms-valid", id: "carriers-instance"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xxforms-valid", id: "countries-names-instance"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xxforms-valid", id: "countries-instance"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xxforms-valid", id: "country-details-instance"}
event - end dispatching {time (ms): "0"}
model - end performing revalidate {time (ms): "4"}
event - end dispatching {time (ms): "4"}
event - start dispatching {name: "xforms-refresh", id: "main-model"}
model - start performing refresh {model id: "main-model"}
controls - start cloning
controls - end cloning {time (ms): "0"}
controls - start updating bindings
controls - end updating bindings {time (ms): "11", controls updated: "91", repeat iterations: "0"}
event - start dispatching {name: "xforms-value-changed", id: "age-input-control"}
event - end dispatching {time (ms): "0"}
event - start dispatching {name: "xforms-enabled", id: "age-input-control"}
event - end dispatching {time (ms): "0"}
model - end performing refresh {time (ms): "17"}
event - end dispatching {time (ms): "17"}
XForms server - end handling external event {time (ms): "33"}
XForms server - end handling external events {time (ms): "33"}
Last modified 1yr ago