Bug 197600

I now discover that System.err also stops going to messages.log.

I've updated the summary and the priority.

I'm stuck trying to debug a problem with my modules and want to see this information. Suggestions?

Works for me with

Product Version: NetBeans IDE Dev (Build 201105190400)
Java: 1.6.0_16; Java HotSpot(TM) Client VM 14.2-b01
System: Windows XP version 5.1 running on x86; Cp1252; en_US (nb)

Can you provide more information and exact steps to reproduce?

I started the IDE with the parameters "--console new -J-Dnetbeans.logger.console=true", created an AnagramGame project, started a debugger and stopped on a breakpoint in the project. The ouput in the console of the NetBeans process is still working.

- started 7.0 with empty userdir.
- new standalone NB module
- new action, put a button into toolbar for it
  actionPerformed: System.err.println("SYSTEM ERR OUTPUT");
- Install/Reload in target IDE (button in toolbar, pressing no output)

- restart IDE
- press button, see output in console

- new java desktop application with main method; set as main project
- add a few lines in main, set a breakpoint in main
- start debugging main
- get the breakpoint
- press button in IDE
observe: no more output to console, no more output to messages.log


Product Version: NetBeans IDE 7.0 (Build 201104080000)
Java: 1.6.0_23; Java HotSpot(TM) Client VM 19.0-b09
System: Windows XP version 5.1 running on x86; Cp1252; en_US (nb)
Userdir: C:\Documents and Settings\erra\.netbeans\TEST

"Install/Reload in Target IDE" is unavailable for standalone module project, but using "Run" for the module project and doing the rest how described (starting debugging against a different project, e.g. AnagramGame sample), stops the output.

This has nothing to do with debugger, it's a bug of TopLogging class.

Initially the standard out and err streams are directly TopLogging$LgStream streams and all works well.
After something is executed externally, they become org.netbeans.core.execution.WriterPrintStream
The org.netbeans.core.execution.OutputStreamWriter for some strange reason *copies* the string into a character array and writes the characters. This should be submitted as a separate performance issue, since in case that the whole string is printed (the majority of cases) this is not necessary.

However, this translation of String into char[] uncovers a defect in TopLogging$LgStream.print(), which for some very strange reason flushes the output only when !Thread.holdsLock(this). But the current thread will always hold the lock, since it's called from java.io.PrintStream.write(PrintStream.java:505), which acquires the lock.

IMHO the simplest fix is to remove the if (!Thread.holdsLock(this)) condition, since it has no sense and seems to be some relict.

I do not know what's the proper category for TopLogging.

FYI: bug #199001 is submitted for the performance inefficiency.

I've fixed bug #199001 and that means that this bug can not be reproduced this way any more.

Please use System.err.print("Char array to stderr.\n".toCharArray()); instead. This does not produce any output.

> Please use System.err.print("Char array to stderr.\n".toCharArray()); instead.
> This does not produce any output.

Sure it does. Just with 5s delay before the output is flushed.

Can you please explain me the mechanism which flushes the output after 5s? I did not experience anything like that, nor anyone else did.

> not experience anything like that, nor anyone else did
Also restore priority.

I've re-read comment #5 and yes, I understand the problem now. I'll do something with it. But the problem does not deserve P2 priority. It does not affect production. Anyway consider using Logger instead of System.err.

(In reply to comment #12)
> the problem does not deserve P2 priority. It does not
> affect production.

This regression affects my production and I hope this can be fixed in 7.0.1.

The plugin I'm working with has a table of over a dozen debug flags which control thousands of output statements. When problems show up in the field it is not uncommon to ask a user to turn on some flag (through a UI) and send the messages.log file.

>  Anyway consider using Logger instead of System.err.

I have, there's a plan; the project pre-dates Logger and it is quite a task.

I am sure Jan can donate a Jackpot rule to convert all System.err to Logger.fine...

(In reply to comment #14)
> I am sure Jan can donate a Jackpot rule to convert all System.err to
> Logger.fine...

Thanks for the thought. I use jackpot3.0 once and a while...

To this point I've extended my DebugOption class to be based on Logger Levels (as seen in the UI) and added some print methods to it.

In general I need to turn stuff like
            if(G.someDebugOption.getBoolean()) {
                debug only stuff;
                System.err.println(arg);
                debug only stuff;
                System.err.println(arg);
                debug only stuff;
            }
into something like
            if(G.someDebugOption.getBoolean()) {
                debug only stuff;
                G.someDebugOption.println(arg);
                debug only stuff;
                G.someDebugOption.println(arg);
                debug only stuff;
            }

Haven't given much thought to jackpot rules that might pick out System.err usage when in selected blocks. I wonder if it can be done without custom jackpot code/extensions? I wonder if something like the following can be adapted to multiple System.err scattered through the block?
    if(G.$debug_option.getBoolean()) {
        $stmnts1$
        G.$debug_option.println($arg);
        $stmnts2$
    }

(In reply to comment #15)
> (In reply to comment #14)
> > I am sure Jan can donate a Jackpot rule to convert all System.err to
> > Logger.fine...
> 
> Thanks for the thought. I use jackpot3.0 once and a while...
> 
> To this point I've extended my DebugOption class to be based on Logger Levels
> (as seen in the UI) and added some print methods to it.
> 
> In general I need to turn stuff like
>             if(G.someDebugOption.getBoolean()) {
>                 debug only stuff;
>                 System.err.println(arg);
>                 debug only stuff;
>                 System.err.println(arg);
>                 debug only stuff;
>             }
> into something like
>             if(G.someDebugOption.getBoolean()) {
>                 debug only stuff;
>                 G.someDebugOption.println(arg);
>                 debug only stuff;
>                 G.someDebugOption.println(arg);
>                 debug only stuff;
>             }
> 
> Haven't given much thought to jackpot rules that might pick out System.err
> usage when in selected blocks. I wonder if it can be done without custom
> jackpot code/extensions? I wonder if something like the following can be
> adapted to multiple System.err scattered through the block?
>     if(G.$debug_option.getBoolean()) {
>         $stmnts1$
>         G.$debug_option.println($arg);
>         $stmnts2$
>     }

It would be nice if something like this would work, but it does not (for several reasons). I will however attach a script that seems to work reasonably for jvi, although it is not really nice. Notes:
-the wrappedWith is a custom condition. Currently it checks only the System.err.println's parent and its parent, but maybe it should look at the parents in a loop?
-currently, the release701 branch of Jackpot 3.0 needs to be used in combination with a release701 NB build. I currently do not have a binary Jackpot build from this branch, will try to make one.
-the second fix solves a problem where sometimes the queried option is not a DebugOption - the fix can be removed, the Apply Pattern refactoring will just warn about "warnings" which have no fixes (safe to ignore - nothing will happen).
-sadly, there appears to be a problem in Jackpot's indexing, so I would suggest to start with empty var/cache/index before applying the changes. I will take a look on this.

Created attachment 108782 [details]
A sketch of script to convert (some) System.err.println to jvi's DebugOption.println.

(In reply to comment #17)
> A sketch of script to convert (some) System.err.println to jvi's
> DebugOption.println.

Jan,

Wow. Many thanks for this. I've been wanting to dig deeper into Jackpot and I'm sure there will be many hours of joyful discovery (and some cursing) as I learn the exact meaning of every last character in the hint :-)

I'll give it a try after this next jVi release; the window split/move/resize commands are almost ready to put out there.

Unfortunately, the fix of bug #199001 did not solve this problem, since I've applied additional change http://hg.netbeans.org/main/rev/7bf3ac9904d3 that adds synchronization and thus Thread.holdsLock(this) returns true again in the TopLogging class and no output is flushed.

For me this is really quite annoying that I can not use Thread.dumpStack() to debug some problems in the code. I really do not want to bother with loggers for temporary debug constructions. And I believe that I'm not the only one.

This is a regression and it should be fixed. I do not see a point in the
if (!Thread.holdsLock(this)) condition, therefore I'm going to remove it.

Fixed by changeset:   195891:ca8d5f2870f4
http://hg.netbeans.org/main/rev/ca8d5f2870f4

Merged into release701 as changeset:   201056:43298c1e0f78

Integrated into 'main-golden'
Changeset: http://hg.netbeans.org/main-golden/rev/ca8d5f2870f4
User: mentlicher@netbeans.org
Log: #197600 Removing an unnecessary condition, which breaks logging.

Integrated into 'releases'
Changeset: http://hg.netbeans.org/releases/rev/43298c1e0f78
User: mentlicher@netbeans.org
Log: #197600 Removing an unnecessary condition, which breaks logging.
(transplanted from ca8d5f2870f410978aa9445020571e0952d3dab3)

I take this as a request to change ownership of TopLogging class. May I assign remaining issue to you as well?