Today, seemingly spontaneously, we began seeing the following error message above the user/pass form fields on the login page:
Unable to establish connection with server
This happened on our Dev server, which is a bit of a wild west environment. One of the developers tried restarting the iwserver a couple of times before I got to it, but the error persisted.
Oddly enough, the
error only appears when a correct user/pass combo is entered. If an incorrect user/pass combo is entered the expected
Wrong username/password message is displayed.
The following lines appear in the
iwtrace.log at iw.server start
Execution of command /opt/Interwoven/TeamSite/bin/iwldapsync failed (Error: 1) for user: iwts. Retried connect to utility daemon 3 times.
TUtildClient:
penSession UseHttps failed
The following stack appears in the
servletd_out.log:
2009-08-10 18:04:27,505 [http-8080-Processor25] ERROR com.interwoven.ui.teamsite.auth.CSClientContext () - Unexpected authentication failure
com.interwoven.cssdk.common.CSException: openSessionWithSessionString failed(Unable to establish connection with server)
at com.interwoven.cssdk.common.jni.CSOtherJNIServer.beginSessionUsingPassword(Native Method)
at com.interwoven.cssdk.factory.CSLocalFactory.getClient(CSLocalFactory.java:99)
at com.interwoven.ui.teamsite.auth.CSClientContext.createFromPassword(CSClientContext.java:442)
at com.interwoven.ui.teamsite.auth.CSClientContext.create(CSClientContext.java:329)
at com.interwoven.ui.base.impl.context.ContextFactory.createContext(ContextFactory.java:67)
at com.interwoven.ui.base.impl.context.ContextSetImpl.doCreateContext(ContextSetImpl.java:109)
at com.interwoven.ui.base.impl.context.AbstractContextSet.doGetContext(AbstractContextSet.java:331)
at com.interwoven.ui.base.impl.context.AbstractContextSet.getContext(AbstractContextSet.java:295)
at com.interwoven.ui.base.impl.context.AbstractContextSet.getContext(AbstractContextSet.java:255)
at com.interwoven.ui.base.impl.auth.AuthenticationFilter.doFilter(AuthenticationFilter.java:189)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at com.interwoven.ui.base.util.SetRequestEncodingFilter.doFilter(SetRequestEncodingFilter.java:105)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:875)
at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Thread.java:595)
The
iwauthen.log looks like this when you try to log in with a correct username ( note the Timeout! )
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid ThreadHandlePool:
op() VVVVVV
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid ThreadHandlePool:
op() fetching from idle list
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid ThreadHandlePool:
op() idle count now: 8
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid ThreadHandlePool:
op() (822cf38)^^^^^^
[Mon, 10 Aug 2009 18:04:27 EDT] INFO 000000000 hopid HTTP accept proc about to run
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid Inside http protocol handler
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid request loop req_count: 0 max: 20
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid Inside http request handler...
[Mon, 10 Aug 2009 18:04:27 EDT] INFO 000000000 hopid Hopi::Thread about to run protocol
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid Inside AuthenticateUser
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid AuthenticateUser about to receive data
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid >>Inside _RecvData<
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid >>Resetting vchunk_cursor and vchunk_count (iostate 256)<<
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid >>_RecvData returning true (iostate 512)<<
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid AuthenticateUser received data
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid request loop req_count: 1 max: 20
[Mon, 10 Aug 2009 18:04:27 EDT] DEBUG 000000000 hopid Inside http request handler...
[Mon, 10 Aug 2009 18:04:42 EDT] WARN 0004c4b77 hopid Timeout![Mon, 10 Aug 2009 18:04:44 EDT] INFO 000000000 hopid Hopi::Thread protocol completed
[Mon, 10 Aug 2009 18:04:44 EDT] DEBUG 000000000 hopid ThreadHandlePool:
ush() (822cd18) VVVVVV
[Mon, 10 Aug 2009 18:04:44 EDT] DEBUG 000000000 hopid ThreadHandlePool:
ush() 822cd18 idle_count_ (8) != max_idle_ (10)
[Mon, 10 Aug 2009 18:04:44 EDT] DEBUG 000000000 hopid ThreadHandlePool:
ush() 822cd18 idle count now: 9
[Mon, 10 Aug 2009 18:04:44 EDT] DEBUG 000000000 hopid ThreadHandlePool:
ush() ^^^^^^
