[rfc][icedtea-web] pre-review - accidental logging tweeking
Jacob Wisor
gitne at gmx.de
Wed Oct 14 10:38:25 UTC 2015
On 10/13/2015 at 06:15 PM Jiri Vanek wrote:
> Hello!
>
> This (small!!) patch is doing several things. I will post them separately but as
> about 4x4 ways is leading to destination, I wont to share thoughts before
> fulfilling targets of this multi-patch
>
> It started by one bug report and one future request.
> 1 - the bug is, that if set logging to files, and put blocked destination as
> ustom log file (eg "/") whole logging crashes, as initializer of FileLog keeps
> crashing with classNotFound.
> 2 - the feature request was add file-logging of applications run inside in
> itw. I agreed on that that as it gave quite an sense and was supposed to be
> easy. INstead it reviled one fragile area in logging.
>
> Two issues I found during implementation of those two above
> 3 - when verbose is on - junittest may deadlock
> - it went even more wrong during original impelmentations of implementation
> of 1
> 4 - for some already forgotten reason we are using java.util.logging as main
> logging facility for filelogging.
> - imho it is overcomplicated - several synchronizations on unexpeted palces
> and overall complication, where bufferedwritter.write(string) may be enough.
> - as side effect, we may get deadlock anytime application is using custom
> implementation of logger - I faced several on Elluminate. And again it went
> worse (here read: deadlock was more probable)
Before we proceed with any options, I would really urge you to get rid of all
hardcoded thread sleeps for synchronization. There is no need for them and the
time slices you've chosen are absolutely arbirary, and thus may or may not work
on any target machine. So, this is number 1. Number 2, these sleeps are most
probably also the root cause of any deadlocks. If you start relying on arbitrary
thread sleeps for synchronization, this is almost always a sign of bad design.
So, we should look at your design first before we get to any implementation options.
> So - the first is bug, and should be fixed for both head and 1.6 I fixed it by
> moving initializxations to factory method and returning dummy SimpleLogger
> doing nothing if exception occures. Its this part:
>
>
> + public static SingleStreamLogger createFileLog(FileLogType t) {
> + SingleStreamLogger s;
> + try {
> + s = new FileLog(t);
> + } catch (Exception ex) {
> + //we do not wont to block whole logging just because initialization
> error
> + OutputController.getLogger().log(ex);
> + s = new SingleStreamLogger() {
> +
> + @Override
> + public void log(String s) {
> + //dummy
> + }
> +
> + @Override
> + public void close() {
> + //dummy
> + }
> + };
> + }
> + return s;
> + }
>
> Part of it was refactoring in OutputController where FileLogHolder have to keep
> interface of SingleStreamLogger ratehr then impelmentation of FileLog and
> implying override of close().
>
>
>
> When I promissed (2), I thought that I will just create
> + private static class getAppFileLog {
> +
> + //https://en.wikipedia.org/wiki/Double-checked_locking#Usage_in_Java
> + //https://en.wikipedia.org/wiki/Initialization_on_demand_holder_idiom
> + private static volatile SingleStreamLogger INSTANCE =
> FileLog.createFileLog(FileLog.FileLogType.CLIENTAPP);
> + }
> +
> + public SingleStreamLogger getAppFileLog() {
> + return getAppFileLog.INSTANCE;
> + }
>
> next to already existing getFileLog and FileLogHolder.
>
> and on place of
> //clients app's messages are reprinted only to console
> if (s.getHeader().isClientApp){
> return;
> }
> I will jsut log one more line.
>
> However, I found that any modifications here leads to immidate unexpeted and
> rpetty serious deadlock - during various unittest,inruntime and so on... I
> solved them by adding second
> queue and second consume. Well I' was not happy from that... But if (4) will not
> be faced, it will remain the only option for this approach.
>
> When I screwed implementation of (2) so much, that the deadlock in Elluinate was
> 100% I tried to debug it, but as I ended in case that it is theirs custom Logger
> implementation which is the root cause. So I tried to rework FileLog so it do
> not rely in java.util.logging,but on simple FileWriter.
> Astonishingly it solved both (3) and (4) - when only (4) was target.
>
>
> For (2) there is one more approach, of which I'm not 100% sure what impact it
> may have. That approach is to get rid of teeOutptuStream's logic.
> Just for reminder - itw is taking stdout/err and is repalcing them by
> TeeoutputStreem which a) send what it get to original stream and (as second end
> of Tee) it logs this utput to our console.
> My idea is, to get rid of this duplcate-streams logic, and only log the stuff
> our client aplication is printing, And when que of logged messages is read,
> print it to stdout/err as originall application originally desired. Benefit will
> be, that this logging exeption will be rid of, but drawback will be possile
> lagging of messages.
> If this approach will be taken, then I think the seond queue+conslumer will not
> be needed for (2)
>
>
> Now - I would like to fix (1) - i think the patch is ok, I will send it
> separately, and (1) will be fixed for head and 1.6. Mybe push it as it is after
> some silence on this patch.
>
> Then, I would like to implement (2) and fix (4) ideally also (3)
> To do so, I need - a)get rid of teeOutputStream or/and b)getRid of our misuse
> of java.util.Logging and/or/maybeNot implement the second queue (its based on
> what of a) and/or b) will be seelcted.
>
> As I do not know any other cure for (3) then (b), I'm voting for following my
> patch in this email, and to repalce java.util.logging by FileWriter - we do not
> need whole Logging chain in ITW - afaic ...
>
>
> I) If (b) will be agreed on first , then implementation of (2) should be
> revisited and I will again check what is more suitable - whether change of
> TeeStreem or new Queue+consumer (maybe none? but that I doubt a bit)
>
> II) if removal of TeeStream in favour of logging and reprinting custom client
> apps outputs willbe agreed then (b) should be revisited if needed for (2) - but
> as it is the only cure for (3) and issue with (4) is just more hodden, thenI'm
> really for (I)
It's nice that you start thinking but you should probably break up your patches
and give them simple and sane titles, denonting what purpose they are supposed
to serve, for better reading. Because you are struggling with the English
language to make yourself clear, you should start simple, instead of
conditionally hypothesizing.
> diff -r 2682417d5671 netx/net/sourceforge/jnlp/util/logging/FileLog.java
> --- a/netx/net/sourceforge/jnlp/util/logging/FileLog.java Thu Oct 08 11:52:14 2015 +0200
> +++ b/netx/net/sourceforge/jnlp/util/logging/FileLog.java Tue Oct 13 17:23:54 2015 +0200
> @@ -36,8 +36,11 @@
> exception statement from your version. */
> package net.sourceforge.jnlp.util.logging;
>
> +import java.io.BufferedWriter;
> import java.io.File;
> +import java.io.FileOutputStream;
> import java.io.IOException;
> +import java.io.OutputStreamWriter;
> import java.text.SimpleDateFormat;
> import java.util.Date;
> import java.util.logging.FileHandler;
> @@ -55,41 +58,80 @@
> private static SimpleDateFormat fileLogNameFormatter = new SimpleDateFormat("yyyy-MM-dd_HH:mm:ss.S");
> /**"Tue Nov 19 09:43:50 CET 2013"*/
> private static SimpleDateFormat pluginSharedFormatter = new SimpleDateFormat("EEE MMM dd HH:mm:ss ZZZ yyyy");
These date formats need some clean up. If I am assuming correctly then
fileLogNameFormatter formats the name of the log file. So far so good but since
the log file name is locale (and timezone) agnostic or rather should be, the
date and time format should follow the ISO format here. This would also allow
for safe and consistent automated enumeration of log files. Unfortunately, only
since Java 8 there is a simple way to get ISO 8601 formatted date and time. So,
you may want to consider using this SimpleDateFormat for Java 7 and earlier:
new SimpleDateFormat("YYYY-MM-dd'T'HH:mm:ss.S'Z'")
And this is how you convert the local time into UTC (in principle):
final Date date;
new SimpleDateFormat("YYYY-MM-dd'T'HH:mm:ss.S'Z'").format(new Date((date =
Date()).getTime() - TimeZone.getDefault().getOffset(date.getTime())))
There is another way; by setting the user.timezone property to UTC before
formatting, and then setting it back to the initial timezone. But, this is
really not the preferred way to do it since other threads may be depending on
the value of the user.timezone property at the same time.
Please remember that there is literally *never* any need to do custom formatting
of date and time, except to get ISO 8601 formatting in Java 7 and earlier.
Always use either ISO or the locale specific formatting. Java is pretty good at
that.
Furthermore, I am assuming that pluginSharedFormatter is the formatter used for
time stamping messages written into the log file. This may not be locale
agnostic anymore because it is read by human beings. So, this should probably be
DateFormat.getDateTimeInstance(). Or, again a ISO 8601 formatter, if automated
parsing is required.
Besides, fileLogNameFormatter and pluginSharedFormatter should probably be both
final. Again, fileLogNameFormatter and pluginSharedFormatter are terrible names
because they actually do not give a clear clue to what they are for.
> + private static final String defaultloggerName = "IcedTea-Web file-logger";
> + private static final String defaultApploggerName = "IcedTea-Web app-file-logger";
Don't we have a constant for the package/product name, which should be rather
used for this purpose, somewhere?
> + private final BufferedWriter bw;
>
> - private final Logger impl;
> - private final FileHandler fh;
> - private static final String defaultloggerName = "IcedTea-Web file-logger";
> + private static String getPrefixById(FileLogType id) {
> + switch (id) {
> + case NETX:
> + return "itw-javantx-";
> + case CLIENTAPP:
> + return "itw-clienta-";
>
> - public FileLog() {
> - this(false);
> - }
> -
> - public FileLog(boolean append) {
> - this(defaultloggerName, LogConfig.getLogConfig().getIcedteaLogDir() + "itw-javantx-" + getStamp() + ".log", append);
> + }
Fix brace formatting, please.
> + throw new RuntimeException("Unknow id " + id);
> }
Fix "Unknow" to "Unknown", please.
> + private static String getNameById(FileLogType id) {
> + switch (id) {
> + case NETX:
> + return defaultloggerName;
> + case CLIENTAPP:
> + return defaultApploggerName;
>
> -
> - public FileLog(String fileName, boolean append) {
> + }
> + throw new RuntimeException("Unknow id " + id);
Fix "Unknow" to "Unknown", please.
> + }
> +
> + public static enum FileLogType {
> +
Formatting: Discard empty line.
> + NETX, CLIENTAPP
> + }
> +
> + public static SingleStreamLogger createFileLog(FileLogType t) {
> + SingleStreamLogger s;
Please use more verbose variable names instead of just t or s.
> + try {
> + s = new FileLog(t);
> + } catch (Exception ex) {
> + //we do not wont to block whole logging just because initialization error
> + OutputController.getLogger().log(ex);
> + s = new SingleStreamLogger() {
> +
> + @Override
> + public void log(String s) {
> + //dummy
> + }
> +
> + @Override
> + public void close() {
> + //dummy
> + }
> + };
You know that I am not much of a friend of anonymous classes. In this case,
DummySingleStreamLogger would look just great as a nested named class, or may be
even package level class. ;-) It would also help understanding the source code a
bit more when reading.
> + }
> + return s;
> + }
> +
> + private FileLog(FileLogType t) {
> + this(false, t);
Again, variable names...
> + }
> +
> + private FileLog(boolean append, FileLogType id) {
> + this(getNameById(id), LogConfig.getLogConfig().getIcedteaLogDir() + getPrefixById(id) + getStamp() + ".log", append);
> + }
> +
> + //testing constructor
> + FileLog(String fileName, boolean append) {
If this is for testing, shouldn't this be private or at least protected?
> this(fileName, fileName, append);
> }
> -
> +
> public FileLog(String loggerName, String fileName, boolean append) {
> try {
> File futureFile = new File(fileName);
> if (!futureFile.exists()) {
> FileUtils.createRestrictedFile(futureFile, true);
> }
> - fh = new FileHandler(fileName, append);
> - fh.setFormatter(new Formatter() {
> - @Override
> - public String format(LogRecord record) {
> - return record.getMessage() + "\n";
> - }
> - });
> - impl = Logger.getLogger(loggerName);
> - impl.setLevel(Level.ALL);
> - impl.addHandler(fh);
> + bw = new BufferedWriter(new OutputStreamWriter(new FileOutputStream(new File(fileName), append), "UTF-8"));
Why do you force UTF-8 here??? Just go with the default encoding.
> log(new Header(OutputController.Level.WARNING_ALL, Thread.currentThread().getStackTrace(), Thread.currentThread(), false).toString());
> } catch (IOException e) {
> throw new RuntimeException(e);
> @@ -103,11 +145,25 @@
> */
> @Override
> public synchronized void log(String s) {
> - impl.log(Level.FINE, s);
> + try {
> + bw.write(s);
> + if (!s.endsWith("\n")){
Fix brace formatting, please.
> + bw.newLine();
> + }
> + bw.flush();
> + } catch (IOException e) {
> + throw new RuntimeException(e);
> + }
> }
> -
> +
> + @Override
> public void close() {
> - fh.close();
> + try {
> + bw.flush();
> + bw.close();
> + } catch (IOException e) {
> + throw new RuntimeException(e);
> + }
> }
>
> private static String getStamp() {
> diff -r 2682417d5671 netx/net/sourceforge/jnlp/util/logging/OutputController.java
> --- a/netx/net/sourceforge/jnlp/util/logging/OutputController.java Thu Oct 08 11:52:14 2015 +0200
> +++ b/netx/net/sourceforge/jnlp/util/logging/OutputController.java Tue Oct 13 17:23:54 2015 +0200
> @@ -41,8 +41,10 @@
> import java.io.PrintStream;
> import java.io.PrintWriter;
> import java.io.StringWriter;
> +import java.util.Collections;
> import java.util.LinkedList;
> import java.util.List;
> +import java.util.regex.Pattern;
> import net.sourceforge.jnlp.runtime.JNLPRuntime;
> import net.sourceforge.jnlp.util.logging.headers.Header;
> import net.sourceforge.jnlp.util.logging.headers.JavaMessage;
> @@ -105,13 +107,19 @@
> private static final String NULL_OBJECT = "Trying to log null object";
> private PrintStreamLogger outLog;
> private PrintStreamLogger errLog;
> - private List<MessageWithHeader> messageQue = new LinkedList<MessageWithHeader>();
> - private MessageQueConsumer messageQueConsumer = new MessageQueConsumer();
> + private final List<MessageWithHeader> messageQue = new LinkedList<>();
> + private final MessageQueConsumer messageQueConsumer = new MessageQueConsumer();
> Thread consumerThread;
> + private final List<MessageWithHeader> applicationFileLogQueue = new LinkedList<>();
> + private final MessageQueConsumerForAppFileLog messageQueConsumerForAppFileLog = new MessageQueConsumerForAppFileLog();
> + Thread messageQueConsumerForAppFileLogThread;
> +
> /*stdin reader for headless dialogues*/
> private BufferedReader br;
>
> - //bounded to instance
> + /**bounded to instance -
This Javadoc formatting is a bit odd.
> + * Whole internal logging, eg MessageQueConsumer and so on is heavily synchronized. be careful changing anything on it
> + */
> private class MessageQueConsumer implements Runnable {
>
> @Override
> @@ -131,6 +139,35 @@
> }
> }
> };
> +
> + /** bounded to instance -
Again, odd Javadoc formatting.
> + * On contrary, MessageQueConsumerForAppFileLog is absolutely not synchronised at all.
> + * Synchroning it, may lead to various deadlocks with MessageQueConsumer. On contrary,
> + * it do not need to be synchronized as It is getting messages to queue from one thread and reads them via second.
> + * (no more unlike MessageQueConsumer logging stuff)
> + */
> + private class MessageQueConsumerForAppFileLog implements Runnable {
> +
> + private final Pattern rtrim = Pattern.compile("\\s+$");
Should probably be also static.
> +
> + @Override
> + public void run() {
> + while (true) {
> + try {
> + Thread.sleep(100);
No, do not use arbitrary time slices for synchronization. This is a no go.
> + if (!(OutputController.this == null || applicationFileLogQueue.isEmpty())) {
> + while (!applicationFileLogQueue.isEmpty()) {
> + MessageWithHeader s = applicationFileLogQueue.get(0);
> + applicationFileLogQueue.remove(0);
> + getAppFileLog().log(rtrim.matcher(proceedHeader(s)).replaceAll(""));
> + }
> + }
Fix indentation in the try block, please.
> + } catch (Throwable t) {
> + OutputController.getLogger().log(t);
> + }
> + }
> + }
> + };
>
> public synchronized void flush() {
>
> @@ -138,11 +175,12 @@
> consume();
> }
> }
> -
> +
> public void close() {
> flush();
> if (LogConfig.getLogConfig().isLogToFile()){
Fix brace formatting, please.
> getFileLog().close();
> + getAppFileLog().close();
> }
All of close() should probably happen in cascading try-catch-finally control
structures. Something like:
try {
flush();
if (LogConfig.getLogConfig().isLogToFile()) {
getFileLog().close();
getAppFileLog().close();
}
} catch (Throwable t) {
throw t;
} finally {
try {
if (LogConfig.getLogConfig().isLogToFile()) {
if (getFileLog().close() != null) getFileLog().close();
if (getAppFileLog().close() != null) getAppFileLog().close();
}
} catch (Throwable t) {
throw t;
} finally {
if (getAppFileLog().close() != null) getAppFileLog().close();
}
}
Note that starting with Java 7, you can use the try-with-resources control
structure, which makes such constructs more readable. For the purpose of
close(), you may also want to consider for OutputController to implement
Closeable or AutoCloseable.
> }
>
> @@ -155,6 +193,10 @@
> }
> //clients app's messages are reprinted only to console
> if (s.getHeader().isClientApp){
> + if (LogConfig.getLogConfig().isLogToFile()) {
> + //and to separate file log if enabled
> + applicationFileLogQueue.add(s);
> + }
> return;
> }
> if (!JNLPRuntime.isDebug() && (s.getHeader().level == Level.MESSAGE_DEBUG
> @@ -164,14 +206,7 @@
> //must be here to prevent deadlock, casued by exception form jnlpruntime, loggers or configs themselves
> return;
> }
> - String message = s.getMessage();
> - if (LogConfig.getLogConfig().isEnableHeaders()) {
> - if (message.contains("\n")) {
> - message = s.getHeader().toString() + "\n" + message;
> - } else {
> - message = s.getHeader().toString() + " " + message;
> - }
> - }
> + String message = proceedHeader(s);
> if (LogConfig.getLogConfig().isLogToStreams()) {
> if (s.getHeader().level.isOutput()) {
> outLog.log(message);
> @@ -194,6 +229,18 @@
>
> }
>
> + private static String proceedHeader(MessageWithHeader s) {
> + String message = s.getMessage();
> + if (LogConfig.getLogConfig().isEnableHeaders()) {
> + if (message.contains("\n")) {
> + message = s.getHeader().toString() + "\n" + message;
> + } else {
> + message = s.getHeader().toString() + " " + message;
> + }
> + }
> + return message;
> + }
> +
> private OutputController() {
> this(System.out, System.err);
> }
> @@ -228,6 +275,8 @@
> //itw logger have to be fully initialised before start
> consumerThread = new Thread(messageQueConsumer, "Output controller consumer daemon");
> consumerThread.setDaemon(true);
> + messageQueConsumerForAppFileLogThread = new Thread(messageQueConsumerForAppFileLog, "application file log consumer daemon");
> + messageQueConsumerForAppFileLogThread.setDaemon(true);
> //is started in JNLPRuntime.getConfig() after config is laoded
> Runtime.getRuntime().addShutdownHook(new Thread(new Runnable() {
> @Override
> @@ -238,11 +287,13 @@
> }
>
> public void startConsumer() {
> + //no looking to configs here!
> consumerThread.start();
> //some messages were probably posted before start of consumer
> synchronized (this) {
> this.notifyAll();
> }
> + messageQueConsumerForAppFileLogThread.start();
> }
>
> /**
> @@ -335,15 +386,28 @@
>
>
> private static class FileLogHolder {
> -
> +
> //https://en.wikipedia.org/wiki/Double-checked_locking#Usage_in_Java
> //https://en.wikipedia.org/wiki/Initialization_on_demand_holder_idiom
> - private static volatile FileLog INSTANCE = new FileLog();
> + private static volatile SingleStreamLogger INSTANCE = FileLog.createFileLog(FileLog.FileLogType.NETX);
> }
> - private FileLog getFileLog() {
> +
> + private SingleStreamLogger getFileLog() {
> return FileLogHolder.INSTANCE;
> }
>
> + private static class getAppFileLog {
> +
> + //https://en.wikipedia.org/wiki/Double-checked_locking#Usage_in_Java
> + //https://en.wikipedia.org/wiki/Initialization_on_demand_holder_idiom
> + private static volatile SingleStreamLogger INSTANCE = FileLog.createFileLog(FileLog.FileLogType.CLIENTAPP);
> + }
> +
> + public SingleStreamLogger getAppFileLog() {
> + return getAppFileLog.INSTANCE;
> + }
> +
> +
> private static class SystemLogHolder {
>
> //https://en.wikipedia.org/wiki/Double-checked_locking#Usage_in_Java
> diff -r 2682417d5671 netx/net/sourceforge/jnlp/util/logging/PrintStreamLogger.java
> --- a/netx/net/sourceforge/jnlp/util/logging/PrintStreamLogger.java Thu Oct 08 11:52:14 2015 +0200
> +++ b/netx/net/sourceforge/jnlp/util/logging/PrintStreamLogger.java Tue Oct 13 17:23:54 2015 +0200
> @@ -59,6 +59,11 @@
> this.stream = stream;
> }
>
> + @Override
> + public void close() {
> + this.stream.flush();
You may want PrintStreamLogger (or SingleStreamLogger) to implement Closeable or
AutoCloseable and throw all IOExceptions or Exceptions here too.
> + }
> +
>
>
>
> diff -r 2682417d5671 netx/net/sourceforge/jnlp/util/logging/SingleStreamLogger.java
> --- a/netx/net/sourceforge/jnlp/util/logging/SingleStreamLogger.java Thu Oct 08 11:52:14 2015 +0200
> +++ b/netx/net/sourceforge/jnlp/util/logging/SingleStreamLogger.java Tue Oct 13 17:23:54 2015 +0200
> @@ -42,5 +42,6 @@
>
> public void log(String s);
>
> + public void close();
See above, it is probably more adviseable to implement Closeable or
AutoCloseable than just adding a close() method explicitly.
> }
> diff -r 2682417d5671 netx/net/sourceforge/jnlp/util/logging/UnixSystemLog.java
> --- a/netx/net/sourceforge/jnlp/util/logging/UnixSystemLog.java Thu Oct 08 11:52:14 2015 +0200
> +++ b/netx/net/sourceforge/jnlp/util/logging/UnixSystemLog.java Tue Oct 13 17:23:54 2015 +0200
> @@ -65,5 +65,10 @@
> }
> }
>
> + @Override
> + public void close() {
> + //nothing
> + }
> +
>
> }
> diff -r 2682417d5671 netx/net/sourceforge/jnlp/util/logging/WinSystemLog.java
> --- a/netx/net/sourceforge/jnlp/util/logging/WinSystemLog.java Thu Oct 08 11:52:14 2015 +0200
> +++ b/netx/net/sourceforge/jnlp/util/logging/WinSystemLog.java Tue Oct 13 17:23:54 2015 +0200
> @@ -49,6 +49,11 @@
> public void log(String s) {
> //not yet implemented
> }
> +
> + @Override
> + public void close() {
> + //nothing
> + }
Regards,
Jacob
More information about the distro-pkg-dev
mailing list