niedziela, 21 września 2008

Mój ulubiony Exception - java.lang.ArrayIndexOutOfBoundsException

a wszytko zaczęło się od popełnienia przeze mnie aplikacji. JSF, Facelets, Spring, JPA. Nic specjalnego... Poza tym, że na owej aplikacji od czasu do czasu (co kilka dni) wyskakiwał wyjątek java.lang.ArrayIndexOutOfBoundsException, a dokładniej:

09:17:54,784 ERROR [ajp-0.0.0.0-8009-11] (LifecycleDecorator.java:75) - javax.faces.FacesException: java.lang.ArrayIndexOutOfBoundsException: 1
at com.sun.faces.lifecycle.LifecycleImpl.phase(LifecycleImpl.java:306)
at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:144)
at pl.matt.common.LifecycleDecorator.render(LifecycleDecorator.java:71)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:245)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at pl.matt.common.filter.ProcessingTimeFilter.doFilter(ProcessingTimeFilter.java:29)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:179)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:241)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:437)
at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:381)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.ArrayIndexOutOfBoundsException: 1
at com.sun.faces.renderkit.RenderKitUtils.buildTypeArrayFromString(RenderKitUtils.java:719)
at com.sun.faces.renderkit.RenderKitUtils.determineContentType(RenderKitUtils.java:572)
at com.sun.faces.renderkit.RenderKitImpl.createResponseWriter(RenderKitImpl.java:219)
at com.sun.facelets.FaceletViewHandler.createResponseWriter(FaceletViewHandler.java:380)
at com.sun.facelets.FaceletViewHandler.renderView(FaceletViewHandler.java:550)
at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:106)
at com.sun.faces.lifecycle.LifecycleImpl.phase(LifecycleImpl.java:251)
... 24 more


Hmm... O co chodzi? Co ciekawe, błąd występował zawsze, gdy na stronę wchodziła przeglądarka Yanga WorldSearch Bot v1.1/beta (http://www.yanga.co.uk/). Robi się coraz bardziej interesująco, prawda? Przy wystąpieniu błędu, miałem też ustawione logowanie nagłówków HTTP. Oto one:

user-agent: Yanga WorldSearch Bot v1.1/beta (http://www.yanga.co.uk/)
accept: text/html;q=1.0, text/plain;q=1.0, text/;q=0.5, */*;q=0.1
accept-charset: utf-8;q=1.0, windows-1251;q=0.8, cp1251;q=0.8, koi8-r;q=0.8, *;q=0.5
accept-encoding: gzip;q=1.0, deflate;q=1.0, identity;q=0.5, *;q=0
content-length: 0


Niby nic specjalnego (no poza przeglądarką) ale sytuacja dziwna. Aplikacja odpalana jest na JBossie 4.2.1.GA, gdzie implementacją JSFów jest implementacja referencyjna SUNa w wersji 1.2.04-p02. Pobrałem źródła, aby podejrzeć 719 linię klasy RenderKitUtils


private final static String CONTENT_TYPE_SUBTYPE_DELIMITER = "/";

//...

// now split type and subtype
if (typeSubType.indexOf(CONTENT_TYPE_SUBTYPE_DELIMITER) >= 0) {
String[] typeSubTypeParts = Util.split(typeSubType.toString(), CONTENT_TYPE_SUBTYPE_DELIMITER);
type = typeSubTypeParts[0].trim();
subtype = typeSubTypeParts[1].trim();
} else {
type = typeSubType.toString();
subtype = "";
}


linia 719 to
subtype = typeSubTypeParts[1].trim();

Klasa parsuje zatem jeden z nagłówków HTTP gdzie spodziewa się dwóch napisów rozdzielonych "/". Od razu moją uwagę zwrócił nagłówek:
accept: text/html;q=1.0, text/plain;q=1.0, text/;q=0.5, */*;q=0.1 a dokładniej jego część: text/;.

Trop był, trzeba było go jeszcze sprawdzić. Zainstalowałem zatem w FireFoxie wtyczkę Modify Headers która umożliwia... zmodyfikowanie nagłówków HTTP. Skonfigurowałem ją tak, aby zastępowała nagłówek accept wartością text/html;q=1.0, text/plain;q=1.0, text/;q=0.5, */*;q=0.1.



uruchomiłem aplikację, wszedłem na nią Firefoksem i...
bingo. Aplikacja się wywala. Zaglądam w logi:

00:03:13,862 ERROR [LifecycleDecorator] javax.faces.FacesException: java.lang.ArrayIndexOutOfBoundsException: 1
at com.sun.faces.lifecycle.LifecycleImpl.phase(LifecycleImpl.java:306)
at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:144)
at pl.matt.common.LifecycleDecorator.render(LifecycleDecorator.java:71)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:245)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at pl.matt.common.filter.ProcessingTimeFilter.doFilter(ProcessingTimeFilter.java:29)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:179)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:241)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:437)
at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:381)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.ArrayIndexOutOfBoundsException: 1
at com.sun.faces.renderkit.RenderKitUtils.buildTypeArrayFromString(RenderKitUtils.java:719)
at com.sun.faces.renderkit.RenderKitUtils.determineContentType(RenderKitUtils.java:572)
at com.sun.faces.renderkit.RenderKitImpl.createResponseWriter(RenderKitImpl.java:219)
at com.sun.facelets.FaceletViewHandler.createResponseWriter(FaceletViewHandler.java:380)
at com.sun.facelets.FaceletViewHandler.renderView(FaceletViewHandler.java:550)
at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:106)
at com.sun.faces.lifecycle.LifecycleImpl.phase(LifecycleImpl.java:251)
... 24 more

Jest mój ulubiony Exception.

Tak jak w tenisie stołowym serwis to pół punktu, tak w programowaniu powtórzenie błędu to połowa jego poprawienia. Teraz tylko... no właśnie...

odpaliłem aplikację w trybie odpluskiwania (debug).



Analizując stos wywołań natrafiłem na 203. linię klasy RenderKitImpl:
String[] typeArray = context.getExternalContext().getRequestHeaderValuesMap().get("Accept");

O co chodzi? Przydała się wiedza z zakresu... serwletów! Na obiekcie HttpServletRequest wywołana jest metoda getHeaders(), która zwraca obiekt klasy Enumeration reprezentujący nagłówki HTTP o zadanej nazwie, w tym przypadku "Accept".

Jak teraz podmienić nagłówek w obiekcie HttpServletRequest? Nie da się...
Da się natomiast, przefiltrować żądanie HTTP, podmieniając obiekt je reprezentujący na obiekt innej klasy (oczywiście implementującej interfejs HttpServletRequest). Brzmi skomplikowanie? Chyba nie jest tak źle.

Zatem po kolei:

tworzę klasę filtra:

public class ModifyRequestHeaderFilter implements Filter {

public void init(FilterConfig filterConfig) throws ServletException {
}

public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) throws java.io.IOException,
ServletException {
if (req instanceof HttpServletRequest) {
HttpServletRequest request = (HttpServletRequest) req;
req = new HttpServletRequestWrapper(request);
}

chain.doFilter(req, res);
}

public void destroy() {
}
}


metoda
chain.doFilter(req, res);
przekazuje żądanie do dalszego przetworzenia, ale wcześniej, żądanie jest opakowywane:

HttpServletRequest request = (HttpServletRequest) req;
req = new HttpServletRequestWrapper(request);

w obiekt mojej klasy, która przeciąża metodę getHeaders() klasy HttpServletRequest.

Klasa HttpServletRequestWrapper rozszerza klasę javax.servlet.http.HttpServletRequestWrapper, która w zasazdie tylko opakowuje żądanie HTTP. Delegując wywołania wszystkich metod do opakowanego obiektu, właśnie po to, żeby można było przeciążyć wybrane z nich. To przy okazji świetny przykład wzorca dekorator .Tworzę zatem swoją klasę HttpServletRequestWrapper która przy żądniu nagłówków o nazwie "Accept", podmienia w ich treści "text/;" na "text/*;".


public class HttpServletRequestWrapper extends javax.servlet.http.HttpServletRequestWrapper {

private String substitutedHeaderName = "Accept";
private String toReplace = "text/;";
private String replacement = "text/*;";

public HttpServletRequestWrapper(HttpServletRequest request) {
super(request);
}

@SuppressWarnings( { "unchecked" })
@Override
public Enumeration getHeaders(String name) {
if (substitutedHeaderName.equals(name)) {
Enumeration headers = super.getHeaders(name);
List out = new ArrayList();
while (headers.hasMoreElements()) {
String header = (String) headers.nextElement();
if (header.contains(toReplace)) {
header = header.replaceAll(toReplace, replacement);
}
out.add(header);
}
return new IteratorEnumeration(out.iterator());
}
return super.getHeaders(name);
}

}


Trzeba jeszcze zarejestrować całe rozwiązanie w deskryptorze wdrożenia - pliku web.xml. Filtr konfiguruję tak, aby obsługiwał wszystkie żądania odwołujące się do stron JSF.


<filter>
<filter-name>ModifyRequestHeaderFilter</filter-name>
<filter-class>pl.matt.common.filter.ModifyRequestHeaderFilter</filter-class>
</filter>

<filter-mapping>
<filter-name>ModifyRequestHeaderFilter</filter-name>
<url-pattern>*.jsf</url-pattern>
</filter-mapping>


Restart aplikacji i... działa. Serwlety wiecznie żywe. Mateusz wiecznie zadowolony.

2 komentarze:

Unknown pisze...

Ależ z Ciebie śledczy! Czyżbyś reprezentował klona Ziobry?! ;-)

A tak poważnie, to wspaniale czytało się cały wpis. Potrafisz budować napięcie i bach, na końcu rozwiązanie. Obawiam się, że samemu nie zdobyłbym się na takie dochodzenie. Gratuluję cierpliwości. Byłoby wspaniale móc zobaczyć takie prezentacje na spotkaniach Warszawa JUG czy ich konferencjach. Właśnie takich doświadczeń najbardziej potrzeba.

p.s. Czy zgłosiłeś błąd w projekcie Mojarra?

Jacek
Notatnik Projektanta Java EE

MZ pisze...

Już zgłosiłem:
https://javaserverfaces.dev.java.net/issues/show_bug.cgi?id=807

Na JUGa wystąpienie mam w planach już od jakiegoś czasu, ale nie mogę się zebrać, żeby coś przygotować ;).