How to enable opendj debug logs

This topic contains 14 replies, has 2 voices, and was last updated by  Raneeth 9 months ago.

  • Author
    Posts
  • #14651
     Raneeth 
    Participant

    Hi,

    Could you let me know the commands/procedure on how to enable OpenDJ debug logs

    Thanks

    #14652
     Mark Craig 
    Participant

    Have a look at this section in the Admin Guide: https://backstage.forgerock.com/docs/opendj/3.5/admin-guide#troubleshoot-enable-debug-logging.

    Notice that the debug log takes a target, such as an OpenDJ package or class name, for which to log debugging information.

    #14660
     Raneeth 
    Participant

    Thanks Mark,

    I have tried to enable debug logs, but ending up with the below error.
    Any idea/help on this would be great

    #/opt/OpenDJ/bin/dsconfig set-log-publisher-prop –port 4444 –bindDN “cn=admin,o=lmera” –bindPassword ldapadmin –publisher-name “File-Based Debug Logger” –set enabled:true –set default-debug-level:all –no-prompt –trustAll
    Unable to connect to the server at “atrcxb2258” on port 4444

    #14661
     Mark Craig 
    Participant

    Apparently the server is not listening on port 4444, hostname atrcxb2258.

    You can check that the server is running with the command /opt/OpenDJ/bin/status.

    Also check that the hostname is atrcxb2258 and that the Administration Connector port is indeed 4444. That is the default port, but it’s possible that the default port was not used.

    If the server is stopped, you can start it with /opt/OpenDJ/bin/start-ds.

    #14662
     Raneeth 
    Participant

    Yes Mark I have checked it.

    status command shows Administration port is 4444 and hostaname is atrcxb2258

    root@atrcxb2258: /opt/OpenDJ/bin/status

    >>>> Specify OpenDS LDAP connection parameters

    Administrator user bind DN [cn=Directory Manager]: cn=admin,o=lmera

    Password for user ‘cn=admin,o=lmera’:
    Unable to connect to the server at “atrcxb2258” on port 4444

    — Server Status —
    Server Run Status: Started
    Open Connections: 0

    — Server Details —
    Host Name: atrcxb2258
    Administrative Users: cn=admin,o=lmera
    Installation Path: /opt/OpenDJ
    Version: OpenDJ 2.4.4
    Java Version: <not available> (*)
    Administration Connector: Port 4444 (LDAPS)

    — Connection Handlers —
    Address:Port : Protocol : State
    ————-:———-:———
    — : LDIF : Disabled
    0.0.0.0:161 : SNMP : Disabled
    0.0.0.0:389 : LDAP : Enabled
    0.0.0.0:636 : LDAPS : Disabled
    0.0.0.0:1689 : JMX : Disabled

    — Data Sources —
    Base DN: o=lmera
    Backend ID: userRoot
    Entries: <not available> (*)
    Replication: Disabled

    * Information only available if you provide valid authentication information
    when launching the status command.
    ==============================================================================
    On the other side Directory server java process shows its running.

    root@atrcxb2258:/var/svc/log# ps -eaf | ps -ef | grep CIF_OpenDJ_LDAP
    root 28812 1 0 13:26:57 ? 1:48 /opt/sun/jdk/java1.6.0//bin/java -Ds=CIF_OpenDJ_LDAP -Xms256m -Xmx512m -server -Dorg.opends.server.scriptName=start-ds org.opends.server.core.DirectoryServer –configClass org.opends.server.extensions.ConfigFileHandler –configFile /opt/OpenDJ/config/config.ldif

    root@atrcxb2258:/opt/OpenDJ/logs# cat /opt/OpenDJ/logs/server.pid
    28812
    root@atrcxb2258:/opt/OpenDJ/logs#

    Ans the ports are listening to DS java pid 28812

    root@atrcxb2258:/opt/OpenDJ/logs# lsof -i :4444 |grep LISTEN
    java 28812 root 21u IPv6 0xffffa1c07eb6ce00 0t0 TCP *:4444 (LISTEN)
    root@atrcxb2258:/opt/OpenDJ/logs# lsof -i :389 |grep LISTEN
    java 28812 root 22u IPv6 0xffffa1c0673d7740 0t0 TCP *:ldap (LISTEN)
    root@atrcxb2258:/opt/OpenDJ/logs#

    ===============================================================================

    I have tried to start /opt/OpenDJ/bin/start-ds but its getting timeout

    [ Dec 5 13:23:36 Executing start method (“/opt/OpenDJ/bin/start-ds“). ]
    [05/Dec/2016:13:26:57 +0000] category=CORE severity=INFORMATION msgID=132 msg=The Directory Server is beginning the configuration bootstrapping process
    [05/Dec/2016:13:26:57 +0000] category=EXTENSIONS severity=INFORMATION msgID=1049147 msg=Loaded extension from file ‘/opt/OpenDJ/lib/extensions/snmp-mib2605.jar’ (build 2.4.4, revision 7356)
    [05/Dec/2016:13:26:59 +0000] category=CORE severity=NOTICE msgID=458886 msg=OpenDJ 2.4.4 (build 20111007085444Z, R7356) starting up
    [05/Dec/2016:13:27:02 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381717 msg=Installation Directory: /opt/OpenDJ
    [05/Dec/2016:13:27:02 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381719 msg=Instance Directory: /opt/OpenDJ
    [05/Dec/2016:13:27:02 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381713 msg=JVM Information: 1.6.0_51-b32 by Sun Microsystems Inc., 32-bit architecture, 478871552 bytes heap size
    [05/Dec/2016:13:27:02 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381714 msg=JVM Host: atrcxb2258, running SunOS 5.11 x86, 103042809856 bytes physical memory size, number of processors available 32
    [05/Dec/2016:13:27:02 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381715 msg=JVM Arguments: “-Ds=CIF_OpenDJ_LDAP”, “-Xms256m”, “-Xmx512m”, “-Dorg.opends.server.scriptName=start-ds”
    The timeout of ‘200’ seconds to start the server has been reached. You can
    use the argument ‘–timeout’ to increase this timeout
    [ Dec 5 13:30:17 Method “start” exited with status 2. ]

    ====================================================================

    Also server.out shows that Directory Server has started successfully and listening to ports 4444 & 389

    root@atrcxb2258:/opt/OpenDJ/logs# tail /opt/OpenDJ/logs/server.out
    [05/Dec/2016:13:30:21 +0000] category=CORE severity=INFORMATION msgID=720 msg=No worker queue thread pool size specified: sizing automatically to use 64 threads
    [05/Dec/2016:13:30:21 +0000] category=PROTOCOL severity=NOTICE msgID=2556180 msg=Started listening for new connections on Administration Connector 0.0.0.0 port 4444
    [05/Dec/2016:13:30:21 +0000] category=PROTOCOL severity=NOTICE msgID=2556180 msg=Started listening for new connections on LDAP Connection Handler 0.0.0.0 port 389
    [05/Dec/2016:13:30:22 +0000] category=CORE severity=NOTICE msgID=458887 msg=The Directory Server has started successfully
    [05/Dec/2016:13:30:22 +0000] category=CORE severity=NOTICE msgID=458891 msg=The Directory Server has sent an alert notification generated by class org.opends.server.core.DirectoryServer (alert type org.opends.server.DirectoryServerStarted, alert ID 458887): The Directory Server has started successfully
    root@atrcxb2258:/opt/OpenDJ/logs#

    =================================================================

    Not sure what is going wrong here, OpenDJ not able to search ldap and no other commands are working.

    I have tried to enable the debug logs but failed as mentioned earlier.

    #14663
     Mark Craig 
    Participant

    It is not clear from the output whether OpenDJ startup really completed successfully at 13:30:22, or actually failed due to the timeout at 13:30:17.

    If you restart the server with /opt/OpenDJ/bin/stop-ds --restart, does it definitely start cleanly?

    If the server does not restart cleanly, what error messages are recorded during the attempted restart in /opt/OpenDJ/logs/errors?

    If the server does restart cleanly, can the status command connect to the server at “atrcxb2258” on port 4444?

    #14664
     Raneeth 
    Participant

    Hi Mark,

    From the outputs, that’s the ambiguity part,seems like this is strange behaviour,
    but let me give a try on restart and see how t goes.
    Eventually there are no errors captured in /opt/OpenDJ/logs/errors for the above failures

    #14665
     Raneeth 
    Participant

    Stopped and started DS

    #/opt/OpenDJ/bin/stop-ds
    Server already stopped

    [ Dec 6 10:45:24 Executing start method (“/opt/OpenDJ/bin/start-ds”). ]
    [06/Dec/2016:10:48:43 +0000] category=CORE severity=INFORMATION msgID=132 msg=The Directory Server is beginning the configuration bootstrapping process
    [06/Dec/2016:10:48:43 +0000] category=EXTENSIONS severity=INFORMATION msgID=1049147 msg=Loaded extension from file ‘/opt/OpenDJ/lib/extensions/snmp-mib2605.jar’ (build 2.4.4, revision 7356)
    [06/Dec/2016:10:48:44 +0000] category=CORE severity=NOTICE msgID=458886 msg=OpenDJ 2.4.4 (build 20111007085444Z, R7356) starting up
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381717 msg=Installation Directory: /opt/OpenDJ
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381719 msg=Instance Directory: /opt/OpenDJ
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381713 msg=JVM Information: 1.6.0_51-b32 by Sun Microsystems Inc., 32-bit architecture, 478871552 bytes heap size
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381714 msg=JVM Host: atrcxb2258, running SunOS 5.11 x86, 103042809856 bytes physical memory size, number of processors available 32
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381715 msg=JVM Arguments: “-Ds=CIF_OpenDJ_LDAP”, “-Xms256m”, “-Xmx512m”, “-Dorg.opends.server.scriptName=start-ds”
    [ Dec 6 10:52:05 Method “start” exited with status 1.
    ==========================================================
    Observed errors in /opt/OpenDJ/logs/server.out, but there is no error file created /opt/OpenDJ/logs/error

    [06/Dec/2016:10:48:43 +0000] category=CORE severity=INFORMATION msgID=132 msg=The Directory Server is beginning the configuration bootstrapping process
    [06/Dec/2016:10:48:43 +0000] category=EXTENSIONS severity=INFORMATION msgID=1049147 msg=Loaded extension from file ‘/opt/OpenDJ/lib/extensions/snmp-mib2605.jar’ (build 2.4.4, revision 7356)
    [06/Dec/2016:10:48:44 +0000] category=CORE severity=NOTICE msgID=458886 msg=OpenDJ 2.4.4 (build 20111007085444Z, R7356) starting up
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381717 msg=Installation Directory: /opt/OpenDJ
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381719 msg=Instance Directory: /opt/OpenDJ
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381713 msg=JVM Information: 1.6.0_51-b32 by Sun Microsystems Inc., 32-bit architecture, 478871552 bytes heap size
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381714 msg=JVM Host: atrcxb2258, running SunOS 5.11 x86, 103042809856 bytes physical memory size, number of processors available 32
    [06/Dec/2016:10:48:47 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381715 msg=JVM Arguments: “-Ds=CIF_OpenDJ_LDAP”, “-Xms256m”, “-Xmx512m”, “-Dorg.opends.server.scriptName=start-ds”
    [06/Dec/2016:10:52:03 +0000] 0 caught error thread={main(1)} method={initializeConnectionHandler(LDAPConnectionHandler.java:700)} caught={java.io.IOException: Address already in use}
    [06/Dec/2016:10:52:03 +0000] category=PROTOCOL severity=SEVERE_ERROR msgID=2359728 msg=The LDAP connection handler defined in configuration entry cn=Administration Connector,cn=config was unable to bind to 0.0.0.0:4444: IOException(Address already in use)
    [06/Dec/2016:10:52:03 +0000] 1 caught error thread={main(1)} method={main(DirectoryServer.java:9675)} caught={org.opends.server.types.InitializationException: The LDAP connection handler defined in configuration entry cn=Administration Connector,cn=config was unable to bind to 0.0.0.0:4444: IOException(Address already in use)}
    [06/Dec/2016:10:52:03 +0000] category=CORE severity=NOTICE msgID=458891 msg=The Directory Server has sent an alert notification generated by class org.opends.server.core.DirectoryServer (alert type org.opends.server.DirectoryServerShutdown, alert ID 458893): The Directory Server has started the shutdown process. The shutdown was initiated by an instance of class org.opends.server.core.DirectoryServer and the reason provided for the shutdown was An error occurred while trying to start the Directory Server: The LDAP connection handler defined in configuration entry cn=Administration Connector,cn=config was unable to bind to 0.0.0.0:4444: IOException(Address already in use)
    [06/Dec/2016:10:52:03 +0000] category=CORE severity=NOTICE msgID=458955 msg=The Directory Server is now stopped

    Not sure what is the way forward to start the/online DS

    #14666
     Mark Craig 
    Participant

    In fact the error log is named /opt/OpenDJ/logs/errors (finishing with an s).

    If as the messages suggest, port 4444 is already in use when the server restarts, then indeed that is a problem. Is there another server listening on that port, even after you stop OpenDJ?

    #14669
     Raneeth 
    Participant

    No looks like its same DS java process itself

    # lsof -i :4444 |grep LISTEN
    java 20732 root 21u IPv6 0xffffa1c077f3cb80 0t0 TCP *:4444 (LISTEN)
    # lsof -i :389 | grep LISTEN
    java 20732 root 22u IPv6 0xffffa1c072f7fc40 0t0 TCP *:ldap (LISTEN)

    # ps -eaf | grep 20732
    root 20732 1 0 10:14:33 pts/4 0:33 /opt/sun/jdk/java1.6.0//bin/java -Ds=CIF_OpenDJ_LDAP -Xms256m -Xmx512m -server -Dorg.opends.server.scriptName=start-ds org.opends.server.core.DirectoryServer –configClass org.opends.server.extensions.ConfigFileHandler –configFile /opt/OpenDJ/config/config.ldif
    #

    ==============

    Error file was created long back on nov30, after that its not updated

    # cd /opt/OpenDJ/logs/
    # ls -rlt
    total 6906
    -rw——- 1 root root 0 Nov 30 17:56 replication
    -rw-r–r– 1 root root 59 Nov 30 17:57 README
    -rw——- 1 root root 3525847 Nov 30 20:17 access
    -rw——- 1 root root 4179 Nov 30 20:17 errors
    -rw-r–r– 1 root root 2907 Dec 6 10:52 server.out
    # date
    Tue Dec 6 13:05:18 GMT 2016
    #

    #14670
     Mark Craig 
    Participant

    In addition, it looks like the access file has not been updated since Nov 30, either. That should mean that no client applications have accessed the directory since Nov 30.

    When you stopped the server today, the message was “Server already stopped”. Combined with the evidence that the server has not been doing anything useful since Nov 30, I guess something has gone very wrong.

    You might want to kill the process, and then try to start the server again after the process has shut down.

    #15012
     Raneeth 
    Participant

    Thanks Mark,

    Well, I agree with your above post :) and this
    (You might want to kill the process, and then try to start the server again after the process has shut down) has worked for me, I knew it will.
    But still a mystery after old process shutsdown and exited with 0, how it held a lock ?

    —————————————————————————————-
    I have tried to stop it initially which doesnt worked, so I went for kill -9 pid

    [ Dec 20 09:58:22 Method “start” exited with status 0. ]
    [ Dec 21 05:44:27 Stopping because service disabled. ]
    [ Dec 21 05:44:27 Executing stop method (“/opt/OpenDJ/bin/stop-ds”). ]
    [ Dec 21 05:46:27 Method or service exit timed out. Killing contract 16652. ]
    [ Dec 21 05:46:27 Method “stop” failed due to signal KILL. ]
    [ Dec 21 05:46:27 Executing stop method (“/opt/OpenDJ/bin/stop-ds”). ]
    [ Dec 21 05:48:29 Method or service exit timed out. Killing contract 16664. ]
    [ Dec 21 05:48:29 Method “stop” failed due to signal KILL. ]
    [ Dec 21 05:48:29 Executing stop method (“/opt/OpenDJ/bin/stop-ds”). ]
    [ Dec 21 05:50:30 Method or service exit timed out. Killing contract 16671. ]
    [ Dec 21 05:50:30 Method “stop” failed due to signal KILL. ]
    [ Dec 21 05:50:30 Leaving maintenance because disable requested. ]
    [ Dec 21 05:50:30 Disabled. ]

    —————————————————————————————-
    It’s been quite a while, I’ve been working to find out the root cause.
    Below are my findings towards it, interested to know your comments.

    —————————————————————————————–
    /opt/OpenDJ/logs/errors, please note server was stopped on 17/dec

    [17/Dec/2016:19:19:46 +0000] category=CORE severity=NOTICE msgID=458891 msg=The Directory Server has sent an alert notification generated by class org.opends.server.core.DirectoryServer (alert type org.opends.server.DirectoryServerShutdown, alert ID 458893): The Directory Server has started the shutdown process. The shutdown was initiated by an instance of class org.opends.server.core.DirectoryServerShutdownHook and the reason provided for the shutdown was The Directory Server shutdown hook detected that the JVM is shutting down. This generally indicates that JVM received an external request to stop (e.g., through a kill signal)
    [17/Dec/2016:19:19:51 +0000] category=BACKEND severity=NOTICE msgID=9896306 msg=The backend userRoot is now taken offline
    [17/Dec/2016:19:19:51 +0000] category=CORE severity=NOTICE msgID=458955 msg=The Directory Server is now stopped

    When trying to start-ds result is timedout
    (please observer time stamps its in the same time period) wondering, even if method exited with code 2, process has been created :(

    [ Dec 21 07:33:07 Executing start method (“/opt/OpenDJ/bin/start-ds”). ]
    [21/Dec/2016:07:36:32 +0000] category=CORE severity=INFORMATION msgID=132 msg=The Directory Server is beginning the configuration bootstrapping process
    [21/Dec/2016:07:36:32 +0000] category=EXTENSIONS severity=INFORMATION msgID=1049147 msg=Loaded extension from file ‘/opt/OpenDJ/lib/extensions/snmp-mib2605.jar’ (build 2.4.4, revision 7356)
    [21/Dec/2016:07:36:32 +0000] category=CORE severity=NOTICE msgID=458886 msg=OpenDJ 2.4.4 (build 20111007085444Z, R7356) starting up
    [21/Dec/2016:07:36:38 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381717 msg=Installation Directory: /opt/OpenDJ
    [21/Dec/2016:07:36:38 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381719 msg=Instance Directory: /opt/OpenDJ
    [21/Dec/2016:07:36:38 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381713 msg=JVM Information: 1.6.0_51-b32 by Sun Microsystems Inc., 32-bit architecture, 478871552 bytes heap size
    [21/Dec/2016:07:36:38 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381714 msg=JVM Host: atrcxb2258, running SunOS 5.11 x86, 103042809856 bytes physical memory size, number of processors available 32
    [21/Dec/2016:07:36:38 +0000] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381715 msg=JVM Arguments: “-Ds=CIF_OpenDJ_LDAP”, “-Xms256m”, “-Xmx512m”, “-Dorg.opends.server.scriptName=start-ds”
    The timeout of ‘200’ seconds to start the server has been reached. You can
    use the argument ‘–timeout’ to increase this timeout
    [ Dec 21 07:39:52 Method “start” exited with status 2. ]

    But server pid was created today at 07:36, but above log shows its exited with code 2 :(

    # ps -eaf | grep -i CIF_OpenDJ_LDAP
    root 17155 1 0 07:36:32 ? 0:39 /opt/sun/jdk/java1.6.0//bin/java -Ds=CIF_OpenDJ_LDAP -Xms256m -Xmx512m -server -Dorg.opends.server.scriptName=start-ds org.opends.server.core.DirectoryServer –configClass org.opends.server.extensions.ConfigFileHandler –configFile /opt/OpenDJ/config/config.ldif

    atrcxb2258{root} # cat server.pid
    17155

    ———————————————————————————-
    Please note that below is the last message in /opt/OpenDJ/logs/errors

    [17/Dec/2016:19:19:51 +0000] category=CORE severity=NOTICE msgID=458955 msg=The Directory Server is now stopped

    ———————————————————————————-

    So far I have seen this issue in same server for couple of times(only this server), where as in other servers the same activities are going on smoothly without any issue.This is surprising me :)

    ———————————————————————————–

    I hope I have made everything clear, Please let me know if you have anything to say

    • This reply was modified 9 months ago by  Raneeth.
    #15020
     Mark Craig 
    Participant

    From your logs, I do see that OpenDJ has not managed to start successfully since that last message in the errors log. And when it fails to start, the process continues to hang.

    Do you know how the OpenDJ process was killed on Dec. 17?

    [17/Dec/2016:19:19:46 +0000] category=CORE severity=NOTICE msgID=458891 msg=The Directory Server has sent an alert notification generated by class org.opends.server.core.DirectoryServer (alert type org.opends.server.DirectoryServerShutdown, alert ID 458893): The Directory Server has started the shutdown process. The shutdown was initiated by an instance of class org.opends.server.core.DirectoryServerShutdownHook and the reason provided for the shutdown was The Directory Server shutdown hook detected that the JVM is shutting down. This generally indicates that JVM received an external request to stop (e.g., through a kill signal)

    Maybe you are right about trying to activate debugging. In theory, you should do that with the dsconfig command, but clearly that’s not a possibility in this case.

    One thing you might try is compare config/config.ldif before and after enabling debugging with the dsconfig command on a server that is working. The command should create at least one LDAP entry under cn=config that pertains to debugging. Maybe more than one entry, I don’t know.

    If you make sure the OpenDJ process is stopped on the affected server, and carefully copy those entries to the same location in the config/config.ldif of the affected server, you might get some debugging output when trying to start the server.

    Note: It is easy to ruin your server configuration if you edit it by hand, so take care when doing so.

    #15025
     Raneeth 
    Participant

    Well Mark, Thanks.

    Let me give it a try.Hope this helps (fingers crossed!)

    #15032
     Raneeth 
    Participant

    Is there any wrong woth the below command, its not working in any server.
    #

    /opt/OpenDJ/bin/dsconfig set-log-publisher-prop –port 4444 –bindDN “cn=admin,o=lmera” –bindPassword ldapadmin –publisher-name “File-Based Debug Logger” –set enabled:false –set default-debug-level:all –no-prompt –trustAll

Viewing 15 posts - 1 through 15 (of 15 total)

You must be logged in to reply to this topic.

©2017 ForgeRock - we provide an identity and access platform to secure every online relationship for the enterprise market, educational sector and even entire countries. Click to view our privacy policy and terms of use.

Log in with your credentials

Forgot your details?