Hi,
I have a production instance with some heavy traffic on it and am
struggling to track down and fix a problematic SLD that (presumably)
was the cause of a large (~125 lines deep) stack trace the top of
which looks like:
2013-03-13 20:05:43,789 ERROR [renderer.label] - Error adding label to
the label cache
java.lang.IllegalArgumentException: alpha value out of range
at java.awt.AlphaComposite.<init>(AlphaComposite.java:618)
at java.awt.AlphaComposite.getInstance(AlphaComposite.java:688)
at org.geotools.renderer.style.SLDStyleFactory.getComposite(SLDStyleFactory.java:1024)
Obviously, there could be other ways to handle this specific exception
so that's not the point. Due to the number of requests coming in,
looking at the WMS KVP info was not helpful. Adding to the issue, when
I turned on 'default' logging, my log file rotated 3 times within
minutes (yes - 4M/min of logging output).
So two thoughts/ideas:
1) to prevent stack-trace induced DOS, allow truncating the stack
trace as an option - either a fixed length or upon a matching prefix
(javax.servlet.http.HttpServlet.service for example)
2) to help me find the problematic request/SLD/whatever, an option for
request-based logging - this might look like log messages being
collected and logged together (at the end of the response) with the
request info
To keep 2 from invading the code of geotools, perhaps it works by
pushing a specialized handler into the root logger that tracks
messages by thread local. At the end of the request, if
enabled/present, the handler spits out the collected message and the
request context.
Thanks,
--
Ian Schneider
OpenGeo - http://opengeo.org
Enterprise support for open source geospatial.
On Wed, Mar 13, 2013 at 9:40 PM, Ian Schneider <ischneider@anonymised.com> wrote:
2013-03-13 20:05:43,789 ERROR [renderer.label] - Error adding label to
the label cache
java.lang.IllegalArgumentException: alpha value out of range
at java.awt.AlphaComposite.(AlphaComposite.java:618)
at java.awt.AlphaComposite.getInstance(AlphaComposite.java:688)
at org.geotools.renderer.style.SLDStyleFactory.getComposite(SLDStyleFactory.java:1024)
Obviously, there could be other ways to handle this specific exception
so that’s not the point. Due to the number of requests coming in,
looking at the WMS KVP info was not helpful. Adding to the issue, when
I turned on ‘default’ logging, my log file rotated 3 times within
minutes (yes - 4M/min of logging output).
So two thoughts/ideas:
- to prevent stack-trace induced DOS, allow truncating the stack
trace as an option - either a fixed length or upon a matching prefix
(javax.servlet.http.HttpServlet.service for example)
Does that really cause a DOS attack situation? Is the server being unable
to respond? I believe we’ll see a slowdown for sure… wondering how severe though.
I made a quick check around, don’t see any ready made solution to summarize
stack traces in log4j… there’s also the thing that just cutting them won’t do it,
as the interesting part is normally at the end of the stack trace.
Something more interesting might be to log just a couple of method lines for
each “caused by” statement, that might help throwing away the bathwater
without the baby along with it…
- to help me find the problematic request/SLD/whatever, an option for
request-based logging - this might look like log messages being
collected and logged together (at the end of the response) with the
request info
Uh, no, that would require keeping them in memory and would end up causing
other kinds of trouble.
Normally the answer to debugging multithreaded systems is to add the thread
id to the log output using %t in the pattern… something that we could indeed do.
Another thing that I’ve seen in usage in the cases where more than one thread is
involved in processing a request is give each request a unique id, and then propagate
such id around in the code so that all activities related to that request can be
grepped for
Cheers
Andrea
–
Ing. Andrea Aime
@geowolf
Technical Lead
GeoSolutions S.A.S.
Via Poggio alle Viti 1187
55054 Massarosa (LU)
Italy
phone: +39 0584 962313
fax: +39 0584 1660272
mob: +39 339 8844549
http://www.geo-solutions.it
http://twitter.com/geosolutions_it
Andrea,
Thanks for your thoughts on this.
DOS was probably the wrong term(more like a large reduction in
service), but after resolving the issue, the load on the machine went
down significantly and I stopped receiving notifications...
I did find this ( %throwable{n} ), so I'll try it out:
http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/EnhancedPatternLayout.html
One day I'll prototype my log handler and then we can discuss the
_actual_ memory overhead and compare the effectiveness of the
technique against grepping for an id in a log file that's rotating 
On Thu, Mar 14, 2013 at 3:34 AM, Andrea Aime
<andrea.aime@anonymised.com> wrote:
On Wed, Mar 13, 2013 at 9:40 PM, Ian Schneider <ischneider@anonymised.com>
wrote:
2013-03-13 20:05:43,789 ERROR [renderer.label] - Error adding label to
the label cache
java.lang.IllegalArgumentException: alpha value out of range
at java.awt.AlphaComposite.<init>(AlphaComposite.java:618)
at java.awt.AlphaComposite.getInstance(AlphaComposite.java:688)
at
org.geotools.renderer.style.SLDStyleFactory.getComposite(SLDStyleFactory.java:1024)
Obviously, there could be other ways to handle this specific exception
so that's not the point. Due to the number of requests coming in,
looking at the WMS KVP info was not helpful. Adding to the issue, when
I turned on 'default' logging, my log file rotated 3 times within
minutes (yes - 4M/min of logging output).
So two thoughts/ideas:
1) to prevent stack-trace induced DOS, allow truncating the stack
trace as an option - either a fixed length or upon a matching prefix
(javax.servlet.http.HttpServlet.service for example)
Does that really cause a DOS attack situation? Is the server being unable
to respond? I believe we'll see a slowdown for sure... wondering how severe
though.
I made a quick check around, don't see any ready made solution to summarize
stack traces in log4j... there's also the thing that just cutting them won't
do it,
as the interesting part is normally at the end of the stack trace.
Something more interesting might be to log just a couple of method lines for
each "caused by" statement, that might help throwing away the bathwater
without the baby along with it...
2) to help me find the problematic request/SLD/whatever, an option for
request-based logging - this might look like log messages being
collected and logged together (at the end of the response) with the
request info
Uh, no, that would require keeping them in memory and would end up causing
other kinds of trouble.
Normally the answer to debugging multithreaded systems is to add the thread
id to the log output using %t in the pattern.... something that we could
indeed do.
Another thing that I've seen in usage in the cases where more than one
thread is
involved in processing a request is give each request a unique id, and then
propagate
such id around in the code so that all activities related to that request
can be
grepped for
Cheers
Andrea
--
Ing. Andrea Aime
@geowolf
Technical Lead
GeoSolutions S.A.S.
Via Poggio alle Viti 1187
55054 Massarosa (LU)
Italy
phone: +39 0584 962313
fax: +39 0584 1660272
mob: +39 339 8844549
http://www.geo-solutions.it
http://twitter.com/geosolutions_it
-------------------------------------------------------
--
Ian Schneider
OpenGeo - http://opengeo.org
Enterprise support for open source geospatial.
On Thu, Mar 14, 2013 at 4:47 PM, Ian Schneider <ischneider@anonymised.com> wrote:
Andrea,
Thanks for your thoughts on this.
DOS was probably the wrong term(more like a large reduction in
service), but after resolving the issue, the load on the machine went
down significantly and I stopped receiving notifications…
I did find this ( %throwable{n} ), so I’ll try it out:
http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/EnhancedPatternLayout.html
I see… given that the interesting part is usually at the end, maybe use {-n} instead?
One day I’ll prototype my log handler and then we can discuss the
actual memory overhead and compare the effectiveness of the
technique against grepping for an id in a log file that’s rotating
It is sure to be more effective, but it’s also something that cannot be used against
a production system, and is far more dangerous to expose than the current VERBOSE
strategy.
What I mean is, it should be well hidden so that end users do not activate it by mistake.
Maybe activated only when a certain system variable is set?
Cheers
Andrea
–
Ing. Andrea Aime
@geowolf
Technical Lead
GeoSolutions S.A.S.
Via Poggio alle Viti 1187
55054 Massarosa (LU)
Italy
phone: +39 0584 962313
fax: +39 0584 1660272
mob: +39 339 8844549
http://www.geo-solutions.it
http://twitter.com/geosolutions_it