OS X El Capitan "Java 6" dialog when loading libpljava-so-1.5.0-BETA1.bundle referencing Java 8

[kkzz8888]

(Editing this issue for context; the reporter began it on the end of a different issue #94. -Chap)

(This is OS X El Capitan, 10.11.3. After building 1.5.0-BETA1 and setting config variables as follows)

pljava.libjvm_location='/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/server/libjvm.dylib'
pljava.classpath='/usr/local/share/postgresql/pljava/pljava-1.5.0-BETA1.jar'

(The following popup is reported to appear, even though pljava.libjvm_location explicitly refers to an installation of Java 8.)

(otool shows the following libraries coded into the pljava bundle):

otool -L /usr/local/lib/postgresql/libpljava-so-1.5.0-BETA1.bundle 
/usr/local/lib/postgresql/libpljava-so-1.5.0-BETA1.bundle:
    /usr/local/opt/postgresql/lib/libecpg.6.dylib (compatibility version 6.0.0, current version 6.7.0)
    /usr/local/opt/postgresql/lib/libpgtypes.3.dylib (compatibility version 3.0.0, current version 3.6.0)
    /usr/local/opt/postgresql/lib/libpq.5.dylib (compatibility version 5.0.0, current version 5.8.0)
    /usr/lib/libc++.1.dylib (compatibility version 1.0.0, current version 120.1.0)
    /usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1226.10.1)

(There should not be any reference to a different JVM coded in, and there is not, so that is as it should be.)

[jcflack]

Thanks, that eliminates one easy explanation. (Too bad, because I was kind of hoping for the easy explanation. But elimination is good.) There is no linked-in reference to a different JVM to be causing the problem. Somehow, that Java 6 dialog is appearing when PL/Java explicitly tries to load the Java 8 library named in pljava.libjvm_location.

Is there any chance of getting a careful, technical English translation of that dialog?

There is not much information shown by psql after the LOAD command because the backend dies, but would it be possible to

SHOW pljava.libjvm_location;
SET client_min_messages TO debug5;
SET log_min_messages TO debug5;
SET log_error_verbosity TO verbose;

just before the LOAD command, and then attach any messages from around that time found in the server log, as well as those from psql?

[kkzz8888]

Thanks for your help. The dialog message simply means that 'you need to install legacy Java SE 6 to run the Java application'. Similar to this: https://kbpdfstudio.qoppa.com/?p=2393

show pljava.libjvm_location;
                                   pljava.libjvm_location                                    
---------------------------------------------------------------------------------------------
 /Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/server/libjvm.dylib
(1 row)

pega7=# set client_min_messages to debug5;
DEBUG:  CommitTransactionCommand
DEBUG:  CommitTransaction
DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
SET
pega7=# set log_min_messages to debug5;
DEBUG:  StartTransactionCommand
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
DEBUG:  ProcessUtility
DEBUG:  CommitTransactionCommand
DEBUG:  CommitTransaction
DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
SET
pega7=# set log_error_verbosity to verbose;
DEBUG:  StartTransactionCommand
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
DEBUG:  ProcessUtility
DEBUG:  CommitTransactionCommand
DEBUG:  CommitTransaction
DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
SET
pega7=# load '/usr/local/lib/postgresql/libpljava-so-1.5.0-BETA1.bundle';
DEBUG:  StartTransactionCommand
DEBUG:  StartTransaction
DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
DEBUG:  ProcessUtility
DEBUG:  Using integer_datetimes
DEBUG:  Added JVM option string "-Dvisualvm.display.name=PL/Java:1069:pega7"
DEBUG:  Added JVM option string "vfprintf"
DEBUG:  Added JVM option string "-Xrs"
DEBUG:  Added JVM option string "-Djava.class.path=/usr/local/share/postgresql/pljava/pljava-1.5.0-BETA1.jar"
DEBUG:  creating Java virtual machine
DEBUG:  shmem_exit(-1): 1 before_shmem_exit callbacks to make
DEBUG:  shmem_exit(-1): 6 on_shmem_exit callbacks to make
DEBUG:  proc_exit(-1): 3 callbacks to make
server closed the connection unexpectedly
    This probably means the server terminated abnormally
    before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.

server.log:

LOG:  server process (PID 547) exited with exit code 97
LOG:  terminating any other active server processes
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
FATAL:  the database system is in recovery mode
LOG:  all server processes terminated; reinitializing
LOG:  database system was interrupted; last known up at 2016-02-08 21:37:26 EST
LOG:  database system was not properly shut down; automatic recovery in progress
LOG:  invalid record length at 4/B1FFFDC0
LOG:  redo is not required
LOG:  MultiXact member wraparound protections are now enabled
LOG:  database system is ready to accept connections
LOG:  autovacuum launcher started
No Java runtime present, requesting install.
LOG:  server process (PID 572) exited with exit code 97
LOG:  terminating any other active server processes
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
LOG:  all server processes terminated; reinitializing
LOG:  database system was interrupted; last known up at 2016-02-08 21:55:39 EST

[jcflack]

That's an interesting line in the server log: No Java runtime present, requesting install.

What do the buttons on that dialog say? I wonder whether somehow your Java 8 installation did not get completely finished, and somehow OS X thinks it is not usable.

I see some StackOverflow posts where it seems that a button on the dialog might take you to a download page for a current Java version. If it only goes to a Java 6 download that is no good, but if it allows a Java 8 download, maybe it is worth trying. Perhaps if the installation is done through Apple's dialog, it will then be usable, where somehow your previous installation method does not seem to satisfy the OS.

Some comments point to the System Integrity Protection feature in OS X - perhaps it may have blocked some critical part of your Java installation before. Only a guess though.

[jcflack]

By the way, the debug messages all the way up through Creating Java virtual machine prove that the library named in pljava.libjvm_location does exist, and PL/Java was able to open it, and find the JNI_CreateJavaVM entry point in it, and call it. So whatever happens that makes OS X think there is "No Java runtime present" is happening from inside the Java runtime. :) Crazy.

[kkzz8888]

I installed jdk-8u74-macosx-x64.dmg from the official oracle site, no issues at all (run the installation and follow the steps). Never had to deal with SIP issue in OS X. In fact, I am running a web app on tomcat without any issues. Even applet I can run without any issues. All using the java 8 installed.

[jcflack]

All of that may be true, but it is also true that opening /Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/server/libjvm.dylib and calling its JNI_CreateJavaVM function causes OS X to say there is "No Java runtime present" and post a dialog to download one, and that isn't the behavior you want, right?

[jcflack]

I might be inclined to give dtruss a try. You could start a psql session, SELECT pg_backend_pid(); and then from another Terminal window (probably as root) run dtruss -p <the-pid> and try the LOAD command; dtruss will show what system calls are being made. It's possible that a failing syscall will show up not long before the "No java runtime present" message, such as an access attempt to a file that's not there. That might at least reveal what the Java runtime is trying to do, that ends up causing OS X to think it is incomplete.

[kkzz8888]

dtrussoutput.txt
Here go you, thanks!

[dblanch-at-hoplasoftware]

I've tried the installation on El Capitan and it runs smoothly, I have to say that I have a bunch of jvm installed even legacy 1.6

test=# set pljava.libjvm_location TO '/Library/Java/JavaVirtualMachines/jdk1.8.0_65.jdk/Contents/Home/jre/lib/server/libjvm.dylib';
SET
test=# CREATE EXTENSION pljava ;
CREATE EXTENSION
test=# 

test=# CREATE FUNCTION getsysprop(VARCHAR)
test-#   RETURNS VARCHAR
test-#   AS 'java.lang.System.getProperty'
test-#   LANGUAGE java;
CREATE FUNCTION
test=# 
test=# SELECT getsysprop('java.version');
 getsysprop 
------------
 1.8.0_65
(1 row)

test=# 

$/usr/libexec/java_home/ -V
Matching Java Virtual Machines (5):
    1.8.0_65, x86_64:   "Java SE 8" /Library/Java/JavaVirtualMachines/jdk1.8.0_65.jdk/Contents/Home
    1.8.0_51, x86_64:   "Java SE 8" /Library/Java/JavaVirtualMachines/jdk1.8.0_51.jdk/Contents/Home
    1.7.0_71, x86_64:   "Java SE 7" /Library/Java/JavaVirtualMachines/jdk1.7.0_71.jdk/Contents/Home
    1.6.0_65-b14-468, x86_64:   "Java SE 6" /Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home
    1.6.0_65-b14-468, i386: "Java SE 6" /Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home

/Library/Java/JavaVirtualMachines/jdk1.8.0_65.jdk/Contents/Home

[jcflack]

Daniel, thanks for the test.

Do you happen to have JAVA_HOME set in the environment of your postgres backend?

(I think you can check with SELECT pg_backend_pid(); in a psql session, then ps -wwE -p <the-pid> | grep JAVA_HOME in another Terminal.)

-Chap

[jcflack]

Looking at that dtruss output ....

that's got some things I didn't expect.

• It looks just as I would expect an Oracle Java startup to look, for the first 1092 lines.
• At line 1093, it starts messing with /System/Library/Frameworks/JavaVM.framework, which I thought didn't happen with the non-Apple, pure Oracle installs, but possibly I was just mistaken about that. Maybe Apple still provides platform-specific stuff there that Oracle's code depends on. I guess it's normal, because nothing seems to have gone wrong by that point.
• At line 1166, it starts mapping in /System/Library/PrivateFrameworks/JavaLaunching.framework. This is starting to seem more weird.
• At lines 1193 to 1195, it is looking for Contents, Resources, and Support Files within /usr/local/opt/postgresql/bin and of course it doesn't find them. Those look like folders that would belong in a Java installation tree, but why is it looking for them in /usr/local/opt/postgresql/bin? I wonder if it is following some default algorithm for a "no JAVA_HOME value" case, and it looks in the current directory (hmm, maybe not, that's probably the DATADIR), or the directory part of the running program name postgres (that might well be /usr/local/opt/postgresql/bin).
• For curiosity's sake, could you attach output from dtruss java -version and dtruss javac -version?
• I wonder what happens if you export JAVA_HOME=/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/ in the environment where the postgres server is started. (Where to put the setting in OS X so it is used when postgres starts is left as an exercise, but you could check it is there after postgres is started by doing SELECT pg_backend_pid(); and then ps -wwE -p <the-pid>).

[dblanch-at-hoplasoftware]

El 11 feb 2016, a las 1:20, Chapman Flack notifications@github.com escribió:

Daniel, thanks for the test.

Do you happen to have JAVA_HOME set in the environment of your postgres backend?

no, i didn’t

(I think you can check with SELECT pg_backend_pid(); in a psql session, then ps -wwE -p | grep JAVA_HOME in another Terminal.)

test=# select pg_backend_pid();                                                                                               pg_backend_pid 
----------------
          67489
(1 row)

test=# SELECT getsysprop('java.version'); getsysprop

1.8.0_65
(1 row)

$ps -wwE -p 67489
PID TTY TIME CMD
67489 ?? 0:00.32 postgres: postgres test [local] idle

Not working, but I haven’t set any java_home for sure

bash-3.2# su - postgres
hal9001:~ postgres$ echo $JAVA_HOME

hal9001:~ postgres$

[jcflack]

Not working, but I haven’t set any java_home for sure

Hmm. I wonder if you could do a dtruss of the LOAD activity, the same as the OP did earlier (in dtrussoutput.txt) ... I'd be interested to see how far they go the same, and where they diverge.

-Chap

[kkzz8888]

I just installed the old java SE 6, now it works! Clearly somewhere the mac el capitan still reference this. Anyway, at least this is a work around.

[jcflack]

Good news! I trust you've confirmed the version PL/Java is actually using is still 8, right?

I wouldn't mind looking at another dtruss output now that Java 6 is installed, to see where the differences are....

[kkzz8888]

Yup, confirmed using java 8:

select getsysprop('java.version');

getsysprop

1.8.0_74

We probably should document this issue so that other people can save the troubleshooting we went through. Thanks for your expertly help along the way!

[dblanch-at-hoplasoftware]

I have the dtruss dump of my working installation.

Having a glance at it, to me it seems that error probably was because java wasn't properly installed. Probably it needed user confirmation before authorizing java to work on his machine. I vaguely remember a similar issue when I switched to El Capitan, but I'm not 100% sure.

Here you have.
dtruss.txt

[Darsstar]

Hi,

I got a fix for this: don't use server/libjvm.dylib, use jli/libjli.dylib when possible (should be from Java 7 as I understand).
Sources:

• https://bugs.openjdk.java.net/browse/JDK-8064542
• http://mail.openjdk.java.net/pipermail/macosx-port-dev/2014-November/006799.html

Worked on a OS X El Capitan virtual machine running in VirtualBox (ran on my MacBook Pro, so I'm not doing anything illegal)
I started by creating a brand new install of OS X El Capitan.
Installed Xcode, then JDK 8 update 74, then home-brew, then postgres 9.4 and maven via brew. Added the openssl include path to the pljava-so/pom.xml file, build it (1.5.0-BETA1) and ran the jar from pljava-packaging.
I did not modify the JDK. If I use libjvm.dylib instead of libjli.dylib I get the Java 6 popup.

I haven't tested other platforms. If libjli works on other platforms as well, and I correctly understood libjli is now prefered over libjvm than maybe pljava.libjvm_location should be renamed. (It is still in beta)
Installed pljava on Windows 10, jli.dll does not work.

Some query history

-- Executing query:
SET pljava.libjvm_location TO '/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/jli/libjli.dylib';

Query returned successfully with no result in 15 msec.

-- Executing query:
--SET pljava.libjvm_location TO '/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/jli/libjli.dylib';
SELECT sqlj.install_jar(
  'file://'
  '/Users/darsstar/Downloads/pljava-1_5_0b1/pljava-examples/target/pljava-examples-1.5.0-BETA1.jar',
  'examples', true);
NOTICE:  return type javatest.complex is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.complex_in(cstring) RETURNS javatest.complex LANGUAGE java IMMUTABLE RETURNS NULL ON NULL INPUT AS 'UDT[org.postgresql.pljava.example.annotation.ComplexScalar] INPUT'"
NOTICE:  argument type javatest.complex is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.complex_out(javatest.complex) RETURNS cstring LANGUAGE java IMMUTABLE RETURNS NULL ON NULL INPUT AS 'UDT[org.postgresql.pljava.example.annotation.ComplexScalar] OUTPUT'"
NOTICE:  return type javatest.complex is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.complex_recv(internal) RETURNS javatest.complex LANGUAGE java IMMUTABLE RETURNS NULL ON NULL INPUT AS 'UDT[org.postgresql.pljava.example.annotation.ComplexScalar] RECEIVE'"
NOTICE:  argument type javatest.complex is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.complex_send(javatest.complex) RETURNS bytea LANGUAGE java IMMUTABLE RETURNS NULL ON NULL INPUT AS 'UDT[org.postgresql.pljava.example.annotation.ComplexScalar] SEND'"
NOTICE:  return type javatest.varlenaudttest is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.VarlenaUDTTest_in(cstring) RETURNS javatest.VarlenaUDTTest LANGUAGE java VOLATILE AS 'UDT[org.postgresql.pljava.example.annotation.VarlenaUDTTest] INPUT'"
NOTICE:  argument type javatest.varlenaudttest is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.VarlenaUDTTest_out(javatest.VarlenaUDTTest) RETURNS cstring LANGUAGE java VOLATILE AS 'UDT[org.postgresql.pljava.example.annotation.VarlenaUDTTest] OUTPUT'"
NOTICE:  return type javatest.varlenaudttest is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.VarlenaUDTTest_recv(internal) RETURNS javatest.VarlenaUDTTest LANGUAGE java VOLATILE AS 'UDT[org.postgresql.pljava.example.annotation.VarlenaUDTTest] RECEIVE'"
NOTICE:  argument type javatest.varlenaudttest is only a shell
CONTEXT:  SQL statement "CREATE OR REPLACE FUNCTION javatest.VarlenaUDTTest_send(javatest.VarlenaUDTTest) RETURNS bytea LANGUAGE java VOLATILE AS 'UDT[org.postgresql.pljava.example.annotation.VarlenaUDTTest] SEND'"
Total query runtime: 5.4 secs
1 row retrieved.

-- Executing query:
--SET pljava.libjvm_location TO '/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/jli/libjli.dylib';
--SELECT sqlj.install_jar(
--  'file://'
--  '/Users/darsstar/Downloads/pljava-1_5_0b1/pljava-examples/target/pljava-examples-1.5.0-BETA1.jar',
--  'examples', true);
SHOW search_path;
Total query runtime: 19 msec
1 row retrieved.

-- Executing query:
--SET pljava.libjvm_location TO '/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/jli/libjli.dylib';
--SELECT sqlj.install_jar(
--  'file://'
--  '/Users/darsstar/Downloads/pljava-1_5_0b1/pljava-examples/target/pljava-examples-1.5.0-BETA1.jar',
--  'examples', true);
--SHOW search_path;
SELECT sqlj.get_classpath('javatest');
Total query runtime: 30 msec
1 row retrieved.

-- Executing query:
--SET pljava.libjvm_location TO '/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/jli/libjli.dylib';
--SELECT sqlj.install_jar(
--  'file://'
--  '/Users/darsstar/Downloads/pljava-1_5_0b1/pljava-examples/target/pljava-examples-1.5.0-BETA1.jar',
--  'examples', true);
--SHOW search_path;
--SELECT sqlj.get_classpath('javatest');
SELECT sqlj.set_classpath('javatest', 'examples');
Total query runtime: 20 msec
1 row retrieved.

-- Executing query:
--SET pljava.libjvm_location TO '/Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre/lib/jli/libjli.dylib';
--SELECT sqlj.install_jar(
--  'file://'
--  '/Users/darsstar/Downloads/pljava-1_5_0b1/pljava-examples/target/pljava-examples-1.5.0-BETA1.jar',
--  'examples', true);
--SHOW search_path;
--SELECT sqlj.get_classpath('javatest');
--SELECT sqlj.set_classpath('javatest', 'examples');
SELECT javatest.java_addone(3);
Total query runtime: 19 msec
1 row retrieved.

[jcflack]

I got a fix for this: don't use server/libjvm.dylib, use jli/libjli.dylib when possible (should be from Java 7 as I understand).

Great find, thanks! This seems about the ideal solution; just use the existing GUC to point to a different .dylib, no code to change, just the OS X-specific documentation. Perfect, or close to it....

[jcflack]

Covered in documentation in 1.5.0-BETA2.