logging throwables with JRuby stack-traces does not work #25
Comments
|
One thought on this: could we use conversion words like |
|
might work (depends on how it routes the throwable formatting code ... assuming it does not do any of the p.s. with |
Do you have an easy way to reproduce it? I'd like to give it a shot.
While switching logging frameworks is easy for a new project, it's a bit more difficult in practice because of production setups (special
So, it seems that it's really a JVM issue and as long as the logging framework doesn't unwind the stack, we should be good? Maybe we can configure it to not try to print the whole thing (e.g. |
|
I've managed to take a look at the exception handling by running the Litle plugin and trying to add a credit card which isn't valid in Litle ( Here is the default stacktrace I'm getting in the add payment method call: As one can see, the package information isn't that useful. Looking at production logs, the information isn't useful either, so I'm suggesting we make Before the change, YourKit shows that 40% of the exceptions are While the total number of exceptions thrown is far less after the change, understanding the impact in terms of performance gain requires more work. |
I've reproduced with bogacs-plus-plus using stripe (but I expect it to happen with litle as well) - been using a custom build for the last time - from https://github.com/kares/killbill-stripe-plugin/tree/load-testing23 + killbill's load-testing13 branch ... so it's not that easy sorry. but I think I'm finally onto something ... I'm close to confirming the issue was due previous JRuby JIT tunings (mostly
course I do not expect you to switch away ... but I think in the long run it might be beneficial to consider esp. with detailed logging ... async logging using the disruptor library seems to be the new Java logging hotness. for the record to switch I did :
have not run with litle but my primary concern quickly became not seeing exceptions reliably ... this would have early on (at least it seems so now) eliminated the path I went with some added (JRuby) OPTS. |
|
FYI, I've also created #28 (no special JRuby flag). |
|
for the record ... there's probably a difference between Tomcat's and Jetty's (web-app) class-loader. Tomcat does not propagate a thus the issue would only exhibit a throwable being lost with logback/log4j2' extended trace formatting on TC |
I just came across http://blog.takipi.com/how-to-instantly-improve-your-java-logging-with-7-logback-tweaks/, which gives some numbers regarding the logack async appender (http://logback.qos.ch/manual/appenders.html). |
|
(Closed by mistake, so reopened it...) |
|
najs logback pimps, thanks @pierre ... but keep in mind async-appenders versus "true" async-loggers are quite different ... the later employed by log4j2 (as fas as I understand) gets out of the way as fast as possible thus even heavy logging has little impact on business logic flow. the drawback for KB might be that for audit purposes it's simply not a "good" choice due its async-queue nature (just a gut guess of mine). |
😸
Ah, fair enough. I guess I need to read more about it!
For compliance purposes, auditing is done actually at the database layer. Each write database operation is wrapped (see EntitySqlDaoWrapperInvocationHandler if you are curious): who did what when is stored in the table itself ( The reason we are heavy on logging however is to be able to understand errors and what the system is doing at runtime: because the platform is generic (to build any type of billing and payment infrastructure), the business logic is mostly driven by configuration files, which can become quite complicated depending on your use-case. Logs help the developer understand what configuration lead to a subscription being renewed at a given date for instance. On the payment and payment plugins side of things, we also heavily log responses with the gateways, as these can be flaky and inconsistent (especially legacy ones outside North America). Long story short, I'm not attached to any particular framework, as long as it does not get (too much) in the way in terms of performance and we can tweak what goes in the logs at runtime. For example, we use the Logback Luhn Mask converter and a custom ThreadNameBasedDiscriminator for log4jdbc-log4j2.
Going back to your remark, you seem right. I'm seeing different behaviors on both containers, which makes debugging the whole thing even more complicated... |
See discussion here: killbill/killbill-plugin-framework-ruby#25 Signed-off-by: Pierre-Alexandre Meyer <pierre@mouraf.org>
Disable stacktrace package detail by default. See discussion at killbill/killbill-plugin-framework-ruby#25. Signed-off-by: Pierre-Alexandre Meyer <pierre@mouraf.org>
related to "occasional" traces seen as :
some full traces at https://gist.github.com/anonymous/aea6b5a96e05bd2531dc
this seems to be one of the factors for unpredictable behaviour as well as likely a major source of "unreliability" for doing any performance optimizations that involve integrating with JRuby ...
whenever a
Throwableis processed by logback it will try to analyse classes involved in stack-trace elements thus trying to load each class based on it's name, whenever a JRuby internal JIT-ed class name is there it will lead to an exception such as above - under logback effectively loosing the original exception.on logback this seems to end up in a considerable slow-down (that only gets triggered after JRuby warms-up) https://gist.github.com/kares/e914ce2afae287a6059d#file-logback_with_yjp_agent-out
similar behaviour happens with log4j2 as it tries to analyze the stack-trace elements: https://gist.github.com/kares/e914ce2afae287a6059d#file-log4j2-log
WiP but in case you have any feedback please let me know as at this point my paranoia is still growing :)
The text was updated successfully, but these errors were encountered: