Application crashing with `InitGoogleLogging() twice!`

[castlemilk]

This error occurs on the following builds:

<Contents>
<Key>java/heap-profiler-eap/profiler_java_agent.tar.gz</Key>
<Generation>1549049183178861</Generation>
<MetaGeneration>1</MetaGeneration>
<LastModified>2019-02-01T19:26:23.178Z</LastModified>
<ETag>"ef34fe9f34913040e79bb7b2dbce9294"</ETag>
<Size>3243479</Size>
</Contents>
<Contents>
<Key>java/latest/profiler_java_agent.tar.gz</Key>
<Generation>1562601408021116</Generation>
<MetaGeneration>1</MetaGeneration>
<LastModified>2019-07-08T15:56:48.020Z</LastModified>
<ETag>"869f7071cca351238f66606b21a55a9c"</ETag>
<Size>3321410</Size>
</Contents>

Recieving the following logs on application crash:

Picked up JAVA_TOOL_OPTIONS: -agentpath:/opt/cprof/profiler_java_agent.so=-cprof_service=psv2,-cprof_service_version=1.6.0-rc.27,-logtostderr,-minloglevel=0,-cprof_project_id=anz-cx-csp-np-5527c6
I0809 00:49:54.791527    13 entry.cc:267] Profiler agent loaded
I0809 00:49:54.791592    13 entry.cc:148] Prepare JVMTI
F0809 00:49:54.791697    13 utilities.cc:322] Check failed: !IsGoogleLoggingInitialized() You called InitGoogleLogging() twice!
*** Check failure stack trace: ***
    @     0x7f59a76425ed  google::LogMessage::Fail()
    @     0x7f59a7644528  google::LogMessage::SendToLog()
    @     0x7f59a7642183  google::LogMessage::Flush()
    @     0x7f59a7644e5e  google::LogMessageFatal::~LogMessageFatal()
    @     0x7f59a764b363  google::glog_internal_namespace_::InitGoogleLoggingUtilities()
    @     0x7f59a75a3193  cloud::profiler::Agent_OnLoad()
    @     0x7f59ad6fc2ec  Threads::create_vm_init_agents()
    @     0x7f59ad700da9  Threads::create_vm()
    @     0x7f59ad24bf21  JNI_CreateJavaVM
    @     0x7f59ae3bdac6  JavaMain
    @     0x7f59ae5d16db  start_thread
    @     0x7f59adee588f  clone
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007f59ade048f0, pid=1, tid=13
#13`

# JRE version:  (11.0.3+7) (build )
# Java VM: OpenJDK 64-Bit Server VM (11.0.3+7, mixed mode, aot, sharing, tiered, compressed oops, g1 gc, linux-amd64)
# Problematic frame:
# C  [libc.so.6+0x408f0]  abort+0x230
#
# Core dump will be written. Default location: /home/java/core.%e.%p.%t
#
# An error report file with more information is saved as:
# /home/java/hs_err_pid1.log
#
# If you would like to submit a bug report, please visit:
#   https://github.com/AdoptOpenJDK/openjdk-build/issues```

Environment: GKE
Application Java Version: base image from `adoptopenjdk/openjdk11:x86_64-ubuntu-jdk-11.0.3_7`
config: `JAVA_TOOL_OPTIONS= -agentpath:/opt/cprof/profiler_java_agent.so=-cprof_service=psv2,-cprof_service_version=1.6.0-rc.27,-logtostderr,-minloglevel=0,-cprof_project_id=anz-cx-csp-np-5527c6`

[kalyanac]

@castlemilk Does your code also initialize glog?

[aalexand]

@kalyanac I don't think having the app using glog would trigger this. The agent links glog statically, so the app and the agent would get their independent instances of glog.

What I think happens here is that the agent is loaded twice. It's easily reproduced:

@azina:2$ gsutil cp gs://cloud-profiler/java/latest/profiler_java_agent.tar.gz .
Copying gs://cloud-profiler/java/latest/profiler_java_agent.tar.gz...
/ [1 files][  3.2 MiB/  3.2 MiB]                                                
Operation completed over 1 objects/3.2 MiB.                                      
@azina:2$ tar xzvf profiler_java_agent.tar.gz 
NOTICES
profiler_java_agent.so
@azina:2$ java -agentpath:./profiler_java_agent.so -agentpath:./profiler_java_agent.so 
F0809 13:28:45.445152 225512 utilities.cc:322] Check failed: !IsGoogleLoggingInitialized() You called InitGoogleLogging() twice!
*** Check failure stack trace: ***
    @     0x7f7b4784ec9d  google::LogMessage::Fail()
    @     0x7f7b47850bd8  google::LogMessage::SendToLog()
    @     0x7f7b4784e833  google::LogMessage::Flush()
    @     0x7f7b4785150e  google::LogMessageFatal::~LogMessageFatal()
    @     0x7f7b47857953  google::glog_internal_namespace_::InitGoogleLoggingUtilities()
    @     0x7f7b477adc93  cloud::profiler::Agent_OnLoad()
    @     0x7f7b4cdbca1b  Threads::create_vm_init_agents()
    @     0x7f7b4cdbfbda  Threads::create_vm()
    @     0x7f7b4cb9bdb5  JNI_CreateJavaVM
    @     0x7f7b4d132bbf  JavaMain
    @     0x7f7b4d3014e8  start_thread
    @     0x7f7b4d17f22d  __clone
Aborted

[aalexand]

What is the full Dockerfile?

[aalexand]

Also why there are both java/heap-profiler-eap/profiler_java_agent.tar.gz and java/latest/profiler_java_agent.tar.gz in the configuration in the original description? Only one of these should be used at a time.

[castlemilk]

Apologies for the confusion,

I'm saying that for both versions of the profiler it is displaying this error. Where each version was run in isolation alongside the application.

The agentpath is set via the JAVA_TOOL_OPTIONS environment variable, i'll need to double check that there isn't an entrypoint script or something which also adds the agentpath reference.

I'll have to get back to you when I have access to the environment on Monday, thanks for the tip.

[aalexand]

@castlemilk Thanks. Quick thought - do you use GoogleCloudPlatform/openjdk-runtime base image by any chance? That one installs the profiler agent if PROFILER_ENABLE env var is set - https://github.com/GoogleCloudPlatform/openjdk-runtime/blob/master/openjdk-common/src/main/docker/setup-env.d/25-profiler-env.bash

[castlemilk]

No the base image is adoptopenjdk/openjdk11:x86_64-ubuntu-jdk-11.0.3_7 from https://hub.docker.com/r/adoptopenjdk/openjdk11/

[castlemilk]

Looks like it was double instantiation of the javaagent 😳, thanks for your assistance! 🙂

[aalexand]

@castlemilk No problem.