[rfc][icedtea-web] logging to file before file is prepared patch

[Jacob Wisor]

On 09/29/2015 at 07:22 PM Jiri Vanek wrote:
> On 09/29/2015 06:24 PM, Jacob Wisor wrote:
>> On 09/29/2015 at 01:45 PM Jiri Vanek wrote:
>>> Hello!
>>>
>>> I have been noticed about segfault when both debuging anf filelogging is on.
>>>
>>> Issue is caused by printing of information into file before the file is actually
>>> prepared.
>>>
>>> The issue is presented since 1.4 but only 1.6 and head are affected - probably
>>> because thewy are logging somehting more. I would like to push it to 1.5 and up.
>>>
>>> Attached patch is disabling printing to file before the file is actually
>>> prepared.
>>
>> I do not think this is the proper way to do it. You did not even bother to get
>> to the root of the
>> cause.
>>
>>> diff -r b02ae452f99f plugin/icedteanp/IcedTeaPluginUtils.h
>>> --- a/plugin/icedteanp/IcedTeaPluginUtils.h    Thu Sep 24 16:32:30 2015 +0200
>>> +++ b/plugin/icedteanp/IcedTeaPluginUtils.h    Tue Sep 29 13:15:10 2015 +0200
>>> @@ -86,6 +86,7 @@
>>>        plugin_debug_to_console = is_java_console_enabled();                    \
>>>        if (plugin_debug_to_file) {                                             \
>>>             IcedTeaPluginUtilities::initFileLog();                             \
>>> +           file_logs_initiated = true;                                        \
>>>        }                                                                       \
>>
>> The problem is that for any reason opening the log file may fail at any time,
>> also writing to it may
>> fail at any time. So first, you do not know the state of the log file after
>> IcedTeaPluginUtilities::initFileLog() has returned. You just do not. You are
>> just assuming that
>> initialization of the log file _always_ works.
>> Second, it is better to check plugin_file_log for NULL before writing to it.
>> So, things would rather
>> look like this:
>>>     if (plugin_debug_to_file && plugin_file_log) {        \
>> And third, you should better check the return values of all those subsequent
>> printfs because writing
>> to files can fail at any time. Well, you /can/ ignore them but then you could
>> also stop bothering
>> calling any subsequent functions with this file after an error has occurred
>> (because you know they
>> are probably going to fail too).
>
> I'm aware of above behaviour. But what do yo suggest as action after those checks?
>
> If it fails during initialisation, it deserves to fail. And crash report will
> lead to discovering of what was wrong.
>
> And same - when writing fails. What to do? IMHO keep going and hoping for best
> is best to do.

In my experience and with systems growing ever more complex, it is best to 
notify the user as soon as possible of an error. If everything else fails, 
writing to stderr is better than nothing. It just makes life and error analysis 
a lot easier, especially for admins.

Besides, I have noticed that IcedTea-Web does not log into syslog or (today) 
journald. It kind of lacks this feature or maybe default behavior. I know, there 
has been discussion about this on the mailing list previously, and as far as I 
recall, it run more less into a dead end because system logs are utterly 
platform and operating system depended. But, I think IcedTea-Web can or should 
offer this feature, at least for syslog or journald in the Linux world. 
Implemented as a weak dependency, not as a hard dependency. So that BSD guys and 
other fundamental opposers of systemd get their break too. ;-)
But seriously, although Java lacks a sane system logging framework (the current 
implementation is just a joke), IcedTea-Web can implement this in its plug-in, 
which is basically a native shared library that can accomplish just that. All it 
needs to do is just write to the log, so we do not need implement all of the 
logging functionality, like log4j does. We also avoid introducing a new build 
and deployment dependency. This way, messages from the Java and native world get 
logged. I have already implemented this into my Windows port.

> Generally - I would like to have as few logic as possible here. as I do not see
> much effective options what to do in corner cases. Patches welcome.
>>
>> Oh, and limiting a log message size to MESSAGE_SIZE is just wired, absolutely
>> arbitrary, and not
>> really necessary. Furthermore, combining the same message with snprintf
>> multiple times for different
>> output targets is also a waste of computing power.
>
> I rememberer I had both unlimited size and variable with resulted str. But I
> also remember I had quite a lot of strange issues with it. Its two years ago, I
> really do not remember, But I would like to avoid failing into the issues again.
>
>>
>> Check this out:
>> IcedTeaNPPlugin.h:
>>> extern FILE * plugin_file_log;
>>
>> IcedTeaPluginUtils.cc:
>>> void IcedTeaPluginUtilities::initFileLog(){
>>>     if (plugin_file_log != NULL ) {
>>>         //reusing
>>>         return;
>>>     }
>>
>> The initialization of the log file is definitely wrong here: plugin_file_log
>> is going to be of any
>> possible value after loading the shared object into memory. It must have been
>> just pure luck that
>> plugin_file_log has been initialized to NULL after loading for any time
>> logging to file from the
>> shared object has ever worked. If you want to make sure the log file does not
>> get reinitialized
>> after it has been initialized then plugin_file_log must be explicitly
>> initialized to NULL before
>> making any assumptions whether to initialize the log file.
>
> Ok:
>
> - FILE * plugin_file_log;
> + FILE * plugin_file_log = NULL;

I think this is it. I have also looked closer into 
IcedTeaPluginUtilities::initFileLog(), it is a little bit oddly written but 
AFAICT correct. Having said that, you do not need to introduce 
file_logs_initiated and test for it, nor test for plugin_file_log in the 
PLUGIN_ERROR() macro. If plugin_file_log gets initialized to an arbitrary value 
at load time then logging into a file does not get initialized, and 
plugin_debug_to_file will most probably get initialized to an arbitrary value 
too, so both will evaluate to true, hence fprintf attempts to write to an 
uninitialized file pointer, effectively resulting in a SIGSEV.

Regards,

Jacob