Debugging, Dev Mode & Logging

The official page says the whole configuration is reloaded on every request. What happens in 7.4.0 is narrower, and it matters for the speed of the development cycle. On every request ConfigurationManager asks each configuration provider whether its file changed; only when one answers yes does the framework load everything again. To see it, the scratch application was requested, struts.xml was touched, and the next request was logged:

Source: Struts — Reloading Configuration

The resource bundles are different: on a request the framework clears the bundle cache (Resource bundles reloaded at DEBUG), and the next message lookup reads the file again. Editing org/example/bookshelf/BookAction.properties in the exploded WAR changed the title page from Bookshelf to the new text within a request or two in the devMode build (in one run the first request right after the edit still showed the old value), and did not change it in the production build, where the value stayed cached for the life of the application.

An explicit setting wins over devMode. With the four constants that the official page lists for "page rendering is slow", devMode stays on while the reloading stops: after setting struts.i18n.reload and struts.configuration.xml.reload to false in the struts.xml of the scratch application, a changed bundle was no longer picked up and a touched struts.xml no longer produced a reload line.

Source: Struts — Development Mode, Page rendering is slow

A word of caution that the documentation does not give. In 7.4.0 on Tomcat 11 the first configuration reload in devMode left two parts of the framework without their servlet context: after struts.xml changed on disk and the reload had run, /static/* answered 500 (Cannot invoke "java.util.List.iterator()" because "this.pathPrefixes" is null in DefaultStaticContentLoader) and an unmapped action name answered 404 with "Unable to show problem report: …​ servletContext is null" instead of the Problem Report; the actions themselves kept working. A fresh deployment answers 200 for both. It was reproduced with and without the config browser plugin. The practical rule is that the in-place reload is good for the XML of actions and results, and that after a change a developer who sees a 500 under /static or a missing Problem Report should reload the context or restart; setting struts.configuration.xml.reload to false and redeploying for every change avoids it.

Most of the value of devMode is in the log. Three message families explain most of the "my parameter does not arrive" and "my page is empty" reports. The first request below sends two parameters to the Bookshelf, filter, whose setter is annotated, and author, whose setter is not, plus a third, isbn, that has no setter at all:

Source: Struts — Development Mode, What does it do?

The response is 200 in every case, and the page lists both books. The log of the devMode build has a line that no other configuration produces:

Source: Struts — Development Mode, What does it do?

The rule that produces the difference is in the Version Notes: 7.0.0 started to log parameter annotation issues at ERROR level in devMode (WW-5433). A setter that exists but lacks @StrutsParameter is a developer mistake and is shown as an error; a request parameter that matches nothing is just input and stays at DEBUG. The official page on development mode says that an unknown field makes the framework throw an exception; in 7.4.0 nothing is thrown in either case, and the only change is the log level. The old "Unexpected Exception caught setting" message does exist, but only when struts.parameters.requireAnnotations is false: in the scratch application with that constant off, isbn produced

Source: Struts Wiki — Version Notes 7.0.0

and with struts.devMode=false none of these ERROR lines is written. That is the real gain of devMode for the Bookshelf’s developers: the log of the production build at WARN would never mention the rejected author, which is why a developer who tests only against the production configuration can spend an afternoon looking for the cause. The production build has the same information at DEBUG: raising only the org.apache.struts2.interceptor.parameter logger to DEBUG there printed the rejection of setAuthor, the unmatched isbn, and two lines for the hostile names below.

The second family is the rejection of hostile parameter names. A request such as

Source: Struts — Security Guide, Accepted / Excluded patterns

is dropped by the parameter name filters before any setter is looked at. With devMode on the log has two WARN lines, each with a pointer to the Security Guide; with devMode off the same decisions are DEBUG:

Source: Struts — Security Guide, Reduce logging level

The third family is a message that is not about parameters. A page that asks for a key that does not exist prints the key itself, and the log says why; the same request prints the WARN lines in both builds, because a missing key is not a devMode feature:

Source: Struts — Logging, Logging support

The OGNL security settings of the framework (the allowlist, the excluded classes and packages) are described on the page on the value stack and in the security hardening page. Two facts belong here because they only apply in devMode. First, struts-excluded-classes.xml in the 7.4.0 jar has a second set of the exclusion constants: struts.devMode.excludedClasses, struts.devMode.excludedPackageNames, struts.devMode.excludedPackageNamePatterns and struts.devMode.excludedPackageExemptClasses. When devMode is on the guard uses these sets. Comparing the two sets in the jar, the devMode class list is the normal one without org.apache.struts2.ActionContext; the package lists are the same. That is consistent with the debugging tools, which read the context, although the files do not say so. Second, the Version Notes of 7.4.0 say that five dev-mode setters of SecurityMemberAccess were removed while the struts.devMode.* settings themselves are unchanged (WW-5675); code that configured the guard through those setters needs the constants instead.

At start-up the guard says which set it uses, which is the quickest way to find out whether a deployed instance still runs in devMode:

Source: Struts Wiki — Version Notes 7.4.0

The most useful mode in 7.4.0 is browser. For the Bookshelf, books?author=Herbert&filter=Dune&debug=browser returns a table with one row for each property of the action; the values are those after parameter injection, so a parameter that was rejected is still null:

Source: Struts — Debugging Interceptor, Parameters

The table is built from a plain request, so it also tells you whether filter arrived. With object=%23parameters (the # must be written %23) the table shows the request parameters as the framework saw them. With object=%23session it shows the session attributes; the Bookshelf’s session held one attribute, named nonce, a security value that a production page must never show. object=%23context returned a single row root null in 7.4.0; the documented default of #context is not what is shown when object is absent, which is the action.

One property of the mode that is easy to miss: the action runs. The log of a debug=browser request has the line Executing action method = execute and the application’s own Listing books with filter [Dune], then No result returned for action ..., because the interceptor replaced the result. The Getting Started page says that the interceptor halts further execution of the action, and the Debugging Interceptor page says that its work happens before the natural result runs. In 7.4.0 "halts" is only true of command, where the log has the debugging interceptor and then No result returned without an execute line. A debug=xml or debug=browser request to an action that saves a book or sends an e-mail therefore does that, once.

Source: Struts — Getting Started, Using the Debugging Interceptor

command evaluates an OGNL expression against the value stack and returns the text of the result. It is the engine behind the OGNL console, and it can be called directly:

Source: Struts — Debugging Interceptor, Example

The security guards apply to the console as they do to any expression, and the guard decides in silence: the answer for a method call is the word null, not an error. Requesting expression=titles.size() returned null; so did titles.get(0), a static call to java.lang.System, and the construction of a java.io.File. The reason is in the log, and finding it is the exercise the next section works through:

Source: Struts — Debugging Interceptor, Parameters

debug=console is a convenience for a browser. The response is a small HTML page whose script opens /static/webconsole.html in a popup (the popup blocker has to allow it, as the Core Developer Guide notes). Two quirks of 7.4.0 were observed. A client that has no session yet gets the console page followed by a Problem Report with IllegalStateException: Cannot create a session after the response has been committed, because the interceptor writes the response before it stores the value stack in the session; with a session cookie from an earlier request it works, and the page of the action follows the popup script. And the console resources are served only in devMode.

The console is a remote expression evaluator. Everything on this page about "never in production" is about this mode: the guard blocks the dangerous classes, but an interface that evaluates OGNL on request and is reachable by an attacker depends on that guard having no gap, which is more than a production system should rely on.

Source: Struts — Debugging

The documented output of debug=xml is a <debug> element with <parameters/>, <context>, <request/>, <session/> and <valueStack>. In 7.4.0 the response of the scratch application starts correctly and ends in the middle of a tag:

Source: Struts — Debugging Interceptor, Example

The status is 200 and the content type is text/xml. The cause is in the Problem Report: UnsupportedOperationException: method makes no sense for a simplified map, raised by AttributeMap.size when DebuggingInterceptor.serializeIt checks whether the attr map was already serialized. It was the same on every action and with or without a session. Use browser, which does not serialize that map; a build that needs a complete dump of one request can use <s:debug/> (next section) or a breakpoint.

Because debugging is an ordinary interceptor, it takes the disabled parameter that every interceptor of 7.4.0 accepts (the page on interceptors lists the parameters). The quiet action of the Bookshelf, shown at the top, passes debugging.disabled to defaultStack; with devMode on, quiet?filter=Dune&debug=command&expression=filter returned the normal list page, while books?filter=Dune&debug=command&expression=filter returned Dune.

Source: Struts — Debugging Interceptor

This is useful for the one action that handles the card number of a payment and that should never be dumpable even on a developer’s machine. It is not a substitute for turning devMode off. Also note that the stack matters: an action mapped to paramsPrepareParamsStack, as the chain-stack action of the scratch application is, answered debug=command&expression=filter with the normal list page, because that stack, unlike defaultStack, does not contain the debugging interceptor. Such an action has no debug modes at all.

Source: Struts — Interceptors, Stacking Interceptors

The Logging page says that struts2-core "declares log4j-api and log4j-core". In the 7.4.0 POM only log4j-api is a normal dependency; log4j-core is declared with test scope, so it is not transitive. A WAR that depends on struts2-core alone has the API and no implementation. The scratch WAR without any implementation started and served pages, and its start-up wrote

Source: Struts — Logging, Routing Struts logging elsewhere

and from then on only ERROR entries reached Tomcat’s catalina.out, unformatted (ERROR Dispatcher Could not find action or result: /g12debuggingnolog/nosuch); every WARN, INFO and DEBUG entry of the framework was dropped, which includes all the messages of the previous sections. The application therefore declares the implementation. The struts2-bom does not manage its version (the build failed with "dependencies.dependency.version is missing"), so the version is written out; the one that matches the log4j-api that Struts 7.4.0 brings is 2.26.1:

Source: Struts — Logging, Logging support

The Bookshelf’s own scratch POM names log4j-slf4j2-impl, which brings log4j-core and a bridge for libraries that log to SLF4J. The bridge is a separate concern, as the Logging page says; add log4j-slf4j2-impl (SLF4J 2) or log4j-jcl (Commons Logging) only when a library of the application needs it. The Logging page adds that 6.11.0 still declares slf4j-api and that 7.3.0 dropped it from struts2-core; it had been optional, so nothing changes on the class path of an application.

The configuration of the development build writes to a file that is easy to find in Tomcat’s logs directory and raises two loggers: the framework’s root package and the application’s. The file appender uses the system property that Tomcat sets for its base directory:

Source: Struts — Getting Started, Struts Logging

A word about the logger names. The Getting Started tutorial and the Security Guide both configure com.opensymphony.xwork2 next to org.apache.struts2 (the tutorial says that "the two major packages …​ com.opensymphony and org.apache.struts2" are the ones to raise). No class of 7.4.0 lives in com.opensymphony; the XWork packages were renamed in 7.0.0 (WW-3714 in its Version Notes) and what remains is org.apache.struts2 and its sub-packages. A logger for a name that does not exist is harmless but does nothing, and the line is a leftover that is worth deleting when you copy an old configuration.

At DEBUG the framework is chatty: one request to books?filter=Dune&author=Herbert&isbn=1 produced 96 log lines, among them the exact order in which interceptors ran (Executing conditional interceptor: exception, alias, servletConfig, i18n, csp, prepare, chain, scopedModelDriven, modelDriven, params, conversionError, coep, coop, fetchMetadata, validation, workflow, debugging), every SecurityMemberAccess check, the type converter lookup for filter, Executing action method = execute, the action’s own Listing books with filter [Dune], the result processing and the JSP forward. For a developer this is a trace of the request cycle of the architecture page, in order, and it is worth reading once.

Source: Struts — Logging, Usage

The 96 lines are too many for daily work. Log4j 2 loggers are hierarchical, so a configuration can leave the framework at WARN and raise only the package one is investigating. The configuration below keeps org.apache.struts2 at warn, raises the parameter handling (ParametersInterceptor and StrutsParameterAuthorizer) to debug, and keeps the application at debug. The same request then produced 18 lines, which show the decision for every parameter and the application’s own message:

Source: Apache Log4j 2 — Configuration, Automatic configuration

The loggers that answer the most common questions, with the level at which they start to speak, are:

Source: Struts — Security Guide, Reduce logging level

When an OGNL expression finds no property, the value is empty and nothing is logged, which is why <s:property value="owner.name"/> prints an empty string for a typo. The constant struts.ognl.logMissingProperties (default false; the comment in default.properties warns that it is very verbose) turns on a WARN per property. With it set to true the title page of the Bookshelf logged

Source: Struts — Core Developer Guide, default.properties

together with a handful of lines for framework-internal names (struts, struts.actionMapping, struts.valueStack) that the framework probes on every page. Switch it on for a debugging session and off again; the lines for the internal names make it unsuitable as a permanent setting.

An action logs with the Log4j 2 API like any class, as the Bookshelf’s BookAction does. Two rules from the Logging page are worth repeating. The message syntax is the {} placeholder of Log4j 2 parameterised messages (LOG.debug("... [{}]", filter)), not the #0 syntax of the removed XWork logger. And a java.util.logging.Logger injected into a managed bean by the old container binding no longer exists in 7.3.0 and later; declare the logger as a static final field. The LOG of the Bookshelf printed its line at DEBUG in the development build and, in the production build, where the logger is at info, nothing.

Source: Struts — Logging, Usage

The Javadoc of PrepareOperations has a method for switching devMode on per request: overrideDevMode(boolean) sets an override of the static devMode value for the current thread, with the warning not to set it from a request parameter or any other unprotected source and the suggestion that a signed cookie is one safe way to turn it on per request, and clearDevModeOverride() removes it. The override is read by the debugging interceptor, the <s:debug/> tag and the Problem Report handler (the three classes that call getDevModeOverride() in the 7.4.0 jar); it does not change the OGNL guard or the reloading. The filter below shows how the override is wired, and it is shown as an anti-pattern to recognise, not as part of a production build: it switches devMode, with the debug=command OGNL evaluator, the Problem Report and <s:debug/>, on for any request that carries a static token in a header. It belongs, if anywhere, in a staging or internal-only build, and it must never be deployed where the Internet can reach it. The scratch application ran it on a local Tomcat only:

Source: Struts Javadoc — PrepareOperations.overrideDevMode

The filter is declared before the struts2 filter in web.xml with an opsToken init-param whose value in the scratch application is the placeholder CHANGE_ME (a staging deployment would inject the secret from the environment and never commit it). Requested on the scratch application with struts.devMode=false, without the header or with a wrong one, books?filter=Dune&debug=command&expression=filter returned the list page; with the right header it returned Dune, books-debug showed the <s:debug/> block, and an unmapped action name answered 200 with the Problem Report. Without the header the same URLs behaved as in the production column of the table above.

The method exists and works, and that is the danger. The filter puts an OGNL evaluator behind a static shared secret in a header, which any proxy in the path can log, and it is the same remote evaluator that the Security Guide asks you to remove; it contradicts the rule that devMode is never on in production and the Security Hardening checklist. Do not ship it in a WAR that is deployed where the Internet can reach it, not even disabled by a missing token. For a production incident use the logging route above.