Subject: Re: Starting build-system work (Windows/Mac users please speak up)
To: Kartik Ohri <kartikohri13@gmail.com>
References: <5EC17E17.7070002@anastigmatix.net>
 <CAASLQ4OdOma6h5Mu=hMEPyk0M4-MomYZLnhGH+2wVoL1vt_UEg@mail.gmail.com>
 <5ECED046.3000308@anastigmatix.net>
 <CAASLQ4P11FFgefy_xK0Tcw3vWt1F1MNyVgK5eU=PFGvYrpZcyw@mail.gmail.com>
 <5ED0FCB0.405@anastigmatix.net> <5ED10C6D.2020000@anastigmatix.net>
 <5ED10F36.7060304@anastigmatix.net>
 <CAASLQ4PAQ0PNAxJ5ad9U6o+RT2ip19FXvgoK2y1kGWaJbTZ1WQ@mail.gmail.com>
 <5ED15825.9060504@anastigmatix.net>
 <CAASLQ4OXAb+_J=oK54PH5eYuXjkV9KMsoXEcp-TYaQPqxk1Xbg@mail.gmail.com>
Cc: pljava-dev@lists.postgresql.org
From: Chapman Flack <chap@anastigmatix.net>
Message-ID: <5ED270BA.9010001@anastigmatix.net>
Date: Sat, 30 May 2020 10:42:02 -0400
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101
 Thunderbird/38.7.0
MIME-Version: 1.0
In-Reply-To: 
 <CAASLQ4OXAb+_J=oK54PH5eYuXjkV9KMsoXEcp-TYaQPqxk1Xbg@mail.gmail.com>
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
Precedence: bulk

On 05/30/20 04:35, Kartik Ohri wrote:
> "pljava.vmoptions" changed to
> "-enableassertions:org.postgresql.pljava... -Xcheck:jni"
> 11522020-05-30 08:04:54.113 UTC [10741] LOG:  server process (PID
> 12377) was terminated by signal 6: Aborted
> 11532020-05-30 08:04:54.113 UTC [10741] DETAIL:  Failed process was
> running: CREATE EXTENSION pljava;

Well, I'd say it looks like your work has caught its first PL/Java bug. :)
I've been able to reproduce it here. Right during CREATE EXTENSION too,
not even running the examples later. Good thing this is on 1.6.0-SNAPSHOT...

So, I would say, retain all the work you've done on it so far, but
make it possible to run without -Xcheck:jni for now, until I track
down the bug(s). You might keep working on scripting to condense the
-Xcheck:jni output. It should probably have found something like this:

INFO:  FATAL ERROR in native method: Bad global or local ref passed to JNI
INFO:  	at
org.postgresql.pljava.internal.ExecutionPlan._execute(org.postgresql.pljava.internal@1.6.0-SNAPSHOT/Native
Method)
...
INFO:  	at
org.postgresql.pljava.internal.InstallHelper.groundwork(org.postgresql.pljava.internal@1.6.0-SNAPSHOT/InstallHelper.java:174)


By the way, have you found any way to redirect just the -Xcheck:jni
output somewhere, or only it in combination with other stderr from the
backend?

If it can only be redirected in combination with other stuff, I would
be rather conservative about filtering it. I think I would just want to
recognize and condense the

 WARNING: JNI local refs: %d, exceeds capacity: %d
(
  at ...
|
  - locked <...>
 (a ...)
)*

pattern, which makes up the bulk of the output, and leave anything else
untouched. We don't want to clobber other useful information in the logs,
and even anything from -Xcheck:jni that isn't a local refs capacity warning
should probably be left complete. If it's a FATAL ERROR it won't make the
log file too big, 'cause there'll only be one. :)

Diagnostic messages from Java code generally follow one of these paths:

- they get explicitly sent to PostgreSQL's elog system, and go wherever
  the PostgreSQL logging is pointed, or suppressed depending on the
  enabled log level

- Java exceptions caught and turned into PostgreSQL errors go into the
  PostgreSQL logs at level ERROR.

- Separately, the stack traces of those exceptions are output if the
  PostgreSQL log level is set to DEBUG1 or finer. The code adjusts
  the vfprintf-hook log level (see below) to DEBUG1 before printing
  the stack trace, but I'm not positive it isn't just going to System.err
  and not through the hook. Should be easy enough to confirm, I just
  haven't had to before.

- Messages from the JVM itself that are emitted through a 'vfprintf hook'
  are caught by PL/Java's hook [1] and injected into PostgreSQL's
  elog system at a selectable level, usually INFO. (That is probably
  the path being followed by the -Xcheck:jni messages, explaining
  why they have INFO: in front.)

- Messages that are simply written to Java's System.err *can be* caught
  and included in PostgreSQL's logs, depending on PostgreSQL's
  logging_collector setting. [2] Otherwise, they just go wherever stderr
  was pointing when the PostgreSQL server was started (or wherever
  the server startup scripts point it). That could be, for example,
  the systemd journal.


While filtering with the *idea* of grep seems like the right idea,
I'm not sure the actual grep command will be an easy way to do that.
The 'pattern'

 WARNING: JNI local refs: %d, exceeds capacity: %d
(
  at ...
|
  - locked <...>
 (a ...)
)*

is obviously regular-expression pseudocode, but it's an expression that
spans over multiple lines.

If I were doing it, I would probably write a bit of Python (or jshell,
if you prefer Java) and slurp in the whole log file; conveniently,
both Python and Java have a MULTILINE regular expression option, so
if you wanted you really could translate that pseudocode into a Python
or Java regex and apply it over the whole file across line boundaries.
(Java finally added a method to readAllBytes from a file [3], though
it didn't happen until version 7!)

Regards,
-Chap


[1]
https://github.com/tada/pljava/blob/efbbc1d/pljava-so/src/main/c/Backend.c#L200

[2]
https://www.postgresql.org/docs/9.5/runtime-config-logging.html#GUC-LOGGING-COLLECTOR

[3]
https://docs.oracle.com/javase/7/docs/api/java/nio/file/Files.html#readAllBytes(java.nio.file.Path)