"am_agent_init failed" during OpenAM Web Policy Agent starts up

Background

OpenAM was deployed on Apache Tomcat and Web Agent was deployed in httpd server. Both of them were running in the SAME CentOS server. Yes, I know you might laugh at me: SAME SERVER?
If start service one by by one from command line, there was no error in either the log file of web agent AGENT_DIR/apache22_agent/Agent_##/logs/debug/amAgent or on web pages which uses web agent service.
#Start service one by one
/OPENDJ_DIR/bin/start-ds
/TOMCAT_DIR/bin/startup.sh
/etc/init.d/httpd start 

However, there were errors when you put them either in one run file rc.local with the same run order or in the same order but separated using chkconfig.
#Same order in rc.local file:
OPENDJ_ROOT="/opt/sso/opendj"
TOMCAT_ROOT="/opt/sso/apache-tomcat-7.0.52"
export OPENDJ_ROOT
export TOMCAT_ROOT
cd ${OPENDJ_ROOT}
/bin/su - nctrsso -c "${OPENDJ_ROOT}/bin/start-ds --quiet"
cd ${TOMCAT_ROOT}
/bin/su - nctrsso -c "${TOMCAT_ROOT}/bin/startup.sh"
/etc/init.d/httpd start

Using chkconfig tool to set run order.
#same order but seperate using chkconfig
S11ssoopendj -> ../init.d/ssoopendj
S18ssotomcat -> ../init.d/ssotomcat
S99httpd -> ../init.d/httpd

Symptom

The error were, "403 forbidden" when you visited web page hosted on httpd which use web agent service and "am_agent_init failed" in amAgent log file.

#detailed amAgent error
2014-08-14 09:23:20.351    Error 4841:47170489365360 all: Connection::request() socket not available, error 20
2014-08-14 09:23:20.351    Error 4841:47170489365360 Agent Profile Service: isRESTServiceAvailable(): An error occured while doing naming request. HTTP error
2014-08-14 09:23:20.352    Error 4841:47170489365360 all: agent_worker_init() am_agent_init failed

If I restart httpd server now, both error will go away.
This makes me think that maybe it because when httpd starts and initiates web agent, Tomcat has not fully started yet. 

Checking time stamps of apache log file and amAgent log file, I knew Tomcat started to init on 9:23:22 till 9:24:20; and httpd started to init web agent on 9:23:20. These data prove I am right.


# key timing in tomcat log file
Aug 14, 2014 9:23:22 AM org.apache.catalina.core.AprLifecycleListener init
Aug 14, 2014 9:24:20 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 57158 ms
# key timing in httpd log file
2014-08-14 09:23:20.292       -1 4840:47170489365360 all: Version: 4.0.0-SNAPSHOT
Using ps auxcheck the start time also proves that httpd initiates before tomcat fully started.

Solution

Run these init processes in the same script, rc.local, and let the calling thread sleep 120 seconds before initiating httpd for now, until a better solution is found.

OPENDJ_ROOT="/opt/sso/opendj"
TOMCAT_ROOT="/opt/sso/apache-tomcat-7.0.52"
export OPENDJ_ROOT
export TOMCAT_ROOT
cd ${OPENDJ_ROOT}
/bin/su - nctrsso -c "${OPENDJ_ROOT}/bin/start-ds --quiet"
cd ${TOMCAT_ROOT}
/bin/su - nctrsso -c "${TOMCAT_ROOT}/bin/startup.sh"
sleep 120
/etc/init.d/httpd start
exit 0

No comments:

Post a Comment

Datatable static image not found on the server

When you use ```datatables.min.css``` and ```datatables.min.js``` locally, instead of datatables CDN, you may have encountered that ```sort...