LDAPAuthentication - can't create ePerson at DEBUG

Michael White

unread,

Nov 14, 2017, 8:41:40 AM11/14/17

to dspac...@googlegroups.com

Hi,

DSpace v6.2, JSPUI . . .

I've been working to set up (hierarchical) LDAP based authentication on my DSpace v6.2 DEV system but I'm having problems getting the system to auto-create an ePerson record for new users when the log level is set to DEBUG. In this case, the authentication/creation of the new ePerson fails, and an "EmptyStackException" is thrown when (as far as I can tell) the system attempts to restore the Authorisation state.

With the log level set at INFO, it all works as expected - the new user is authenticated and then the ePerson record is created and the user is logged in - here is a log snippet showing this working as expected at INFO:

2017-11-14 13:20:22,462 INFO org.dspace.authenticate.LDAPAuthentication @ anonymous:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:auth:attempting trivial auth of user=mmw2

2017-11-14 13:20:22,584 INFO org.dspace.authenticate.LDAPAuthentication @ anonymous:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:autoregister:netid=mmw2

2017-11-14 13:20:22,597 INFO org.dspace.eperson.EPersonServiceImpl @ anonymous:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:create_eperson:eperson_id=5955e86d-726f-4ea2-a28d-df92d73aaf15

2017-11-14 13:20:22,680 INFO org.dspace.eperson.EPersonServiceImpl @ anonymous:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:update_eperson:eperson_id=5955e86d-726f-4ea2-a28d-df92d73aaf15

2017-11-14 13:20:22,750 INFO org.dspace.authenticate.LDAPAuthentication @ mike....@stir.ac.uk:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:authenticate:type=ldap-login, created ePerson

2017-11-14 13:20:22,751 WARN org.dspace.core.Context @ mike....@stir.ac.uk:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:restore_auth_sys_state:not previous state info available null

2017-11-14 13:20:22,752 INFO org.dspace.eperson.EPersonServiceImpl @ mike....@stir.ac.uk:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:update_eperson:eperson_id=5955e86d-726f-4ea2-a28d-df92d73aaf15

2017-11-14 13:20:22,855 ERROR org.dspace.core.I18nUtil @ No language specified for EPerson 5955e86d-726f-4ea2-a28d-df92d73aaf15

2017-11-14 13:20:22,856 INFO org.dspace.app.webui.servlet.LDAPServlet @ mike....@stir.ac.uk:session_id=AEFB43EF410423BD73812BA53CFDC825:ip_addr=139.153.86.2:login:type=explicit

2017-11-14 13:20:22,991 INFO org.dspace.app.webui.servlet.MyDSpaceServlet @ mike....@stir.ac.uk:session_id=923FB17CB27F83101481AD719C33997B:ip_addr=139.153.86.2:view_mydspace:

However, with the log level at DEBUG, this fails with the reported Exception:

2017-11-14 13:14:43,178 DEBUG org.dspace.app.webui.servlet.DSpaceServlet @ anonymous:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:http_request:-- URL Was\colon; http\colon;//dspace6dev.stir.ac.uk\colon;8080/jspui/ldap-login

-- Method\colon; POST

-- Parameters were\colon;

-- login_netid\colon; "mmw2"

-- login_password\colon; *not logged*

-- login_submit\colon; "Log In"

2017-11-14 13:14:43,178 DEBUG org.dspace.core.LegacyPluginServiceImpl @ Adding Sequence plugin for interface= org.dspace.authenticate.AuthenticationMethod, class=org.dspace.authenticate.LDAPAuthentication

2017-11-14 13:14:43,178 DEBUG org.dspace.core.LegacyPluginServiceImpl @ Adding Sequence plugin for interface= org.dspace.authenticate.AuthenticationMethod, class=org.dspace.authenticate.PasswordAuthentication

2017-11-14 13:14:43,179 INFO org.dspace.authenticate.LDAPAuthentication @ anonymous:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:auth:attempting trivial auth of user=mmw2

2017-11-14 13:14:43,283 DEBUG org.dspace.authenticate.LDAPAuthentication @ anonymous:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:got DN:CN=mmw2,OU=Enabled,OU=Staff,dc=ad,dc=stir,dc=ac,dc=uk

2017-11-14 13:14:43,292 INFO org.dspace.authenticate.LDAPAuthentication @ anonymous:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:autoregister:netid=mmw2

2017-11-14 13:14:43,310 INFO org.dspace.eperson.EPersonServiceImpl @ anonymous:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:create_eperson:eperson_id=b4a43809-a530-4f26-b300-7910e13ad76e

2017-11-14 13:14:43,351 DEBUG org.dspace.identifier.IdentifierServiceImpl @ Found identifiers: []

2017-11-14 13:14:43,352 DEBUG org.dspace.content.DSpaceObjectServiceImpl @ .

2017-11-14 13:14:43,370 DEBUG org.dspace.core.LegacyPluginServiceImpl @ Adding Sequence plugin for interface= org.dspace.authenticate.AuthenticationMethod, class=org.dspace.authenticate.LDAPAuthentication

2017-11-14 13:14:43,371 DEBUG org.dspace.core.LegacyPluginServiceImpl @ Adding Sequence plugin for interface= org.dspace.authenticate.AuthenticationMethod, class=org.dspace.authenticate.PasswordAuthentication

2017-11-14 13:14:43,371 INFO org.dspace.eperson.EPersonServiceImpl @ anonymous:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:update_eperson:eperson_id=b4a43809-a530-4f26-b300-7910e13ad76e

2017-11-14 13:14:43,406 DEBUG org.dspace.identifier.IdentifierServiceImpl @ Found identifiers: []

2017-11-14 13:14:43,407 DEBUG org.dspace.content.DSpaceObjectServiceImpl @ .

2017-11-14 13:14:43,409 DEBUG org.dspace.event.BasicDispatcher @ Processing queue of 2 events.

2017-11-14 13:14:43,411 DEBUG org.dspace.event.BasicDispatcher @ Iterating over 3 consumers...

2017-11-14 13:14:43,411 DEBUG org.dspace.event.Event @ Filtering event: eventType=1, subjectType=128, result=false

2017-11-14 13:14:43,412 DEBUG org.dspace.event.Event @ Filtering event: eventType=1, subjectType=128, result=false

2017-11-14 13:14:43,413 DEBUG org.dspace.event.Event @ Filtering event: eventType=1, subjectType=128, result=true

2017-11-14 13:14:43,413 DEBUG org.dspace.event.BasicDispatcher @ Sending event to "eperson": org.dspace.event.Event(eventType=CREATE, SubjectType=EPERSON, SubjectID=b4a43809-a530-4f26-b300-7910e13ad76e, ObjectType=(Unknown), ObjectID=null, TimeStamp=1510665283352, dispatcher=1544803905, detail=[null], transactionID="TX5984711716153792285911977537842347528")

2017-11-14 13:14:43,414 DEBUG org.dspace.event.BasicDispatcher @ Iterating over 3 consumers...

2017-11-14 13:14:43,414 DEBUG org.dspace.event.Event @ Filtering event: eventType=2, subjectType=128, result=false

2017-11-14 13:14:43,414 DEBUG org.dspace.event.BasicDispatcher @ Calling end for consumer "versioning"

2017-11-14 13:14:43,415 DEBUG org.dspace.event.BasicDispatcher @ Calling end for consumer "discovery"

2017-11-14 13:14:43,415 DEBUG org.dspace.event.BasicDispatcher @ Calling end for consumer "eperson"

2017-11-14 13:14:43,417 INFO org.dspace.authenticate.LDAPAuthentication @ mike....@stir.ac.uk:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:authenticate:type=ldap-login, created ePerson

2017-11-14 13:14:43,419 WARN org.dspace.core.Context @ mike....@stir.ac.uk:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:restore_auth_sys_state:not previous state info available null

2017-11-14 13:14:43,420 WARN org.dspace.app.webui.servlet.DSpaceServlet @ mike....@stir.ac.uk:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:general_jspui_error:java.util.EmptyStackException

java.util.EmptyStackException

at java.util.Stack.peek(Stack.java:102)

at java.util.Stack.pop(Stack.java:84)

at org.dspace.core.Context.restoreAuthSystemState(Context.java:309)

at org.dspace.authenticate.LDAPAuthentication.authenticate(LDAPAuthentication.java:387)

at org.dspace.authenticate.AuthenticationServiceImpl.authenticateInternal(AuthenticationServiceImpl.java:111)

at org.dspace.authenticate.AuthenticationServiceImpl.authenticate(AuthenticationServiceImpl.java:81)

at org.dspace.app.webui.servlet.LDAPServlet.doDSPost(LDAPServlet.java:78)

at org.dspace.app.webui.servlet.DSpaceServlet.processRequest(DSpaceServlet.java:122)

at org.dspace.app.webui.servlet.DSpaceServlet.doPost(DSpaceServlet.java:80)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

at org.dspace.utils.servlet.DSpaceWebappServletFilter.doFilter(DSpaceWebappServletFilter.java:78)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)

at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)

at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:624)

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)

at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799)

at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)

at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:861)

at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)

at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

at java.lang.Thread.run(Thread.java:748)

2017-11-14 13:14:43,427 DEBUG org.dspace.app.webui.util.JSPManager @ mike....@stir.ac.uk:session_id=FD5A8F4BFB2A5A8B1EC70A560831F10A:ip_addr=139.153.86.2:view_jsp:/error/internal.jsp

This is obviously rather bizarre behaviour (why should the log level affect this?), but I note (from a search of the DSpace archives) it was also reported around a year ago in relation to DSpace v6.0 (https://jira.duraspace.org/browse/DS-3428), but the last comment is from February 2017 and the issue is not marked as resolved.

I will continue to investigate, but wondered if anyone else out there had hit this and, if so, how did you work around it (aside from setting the log level at INFO - I'm still in development, so I really need logging at DEBUG!)?

Cheers,

Mike

Michael White

Senior Developer

Business Applications and Integrations

T: (01786) 466877

E: michae...@stir.ac.uk

A: G5, Airthrey Castle, University of Stirling, Stirling, FK9 4LA

The University achieved an overall 5 stars in the QS World University Rankings 2016/17

The University of Stirling is a charity registered in Scotland, number SC 011159.

Michael White

unread,

Nov 16, 2017, 7:04:48 AM11/16/17

to dspac...@googlegroups.com

Hi,

> I will continue to investigate, but wondered if anyone else out there had hit this and, if so, how did you work around it

Just for the record, and in the absence of any better suggestions, I’ve worked around this by commenting out the following block in [dspace-src]/dspace-api/src/main/java/org/dspace/core/Context.java (around line 303):

/*

if (log.isDebugEnabled())

{

Thread currThread = Thread.currentThread();

StackTraceElement[] stackTrace = currThread.getStackTrace();

String caller = stackTrace[stackTrace.length - 1].getClassName();

String previousCaller = (String) authStateClassCallHistory.pop();

// if previousCaller is not the current caller *only* log a warning

if (!previousCaller.equals(caller))

{

log

.warn(LogManager

.getHeader(

this,

"restore_auth_sys_state",

"Class: "

+ caller

+ " call restore but previous state change made by "

+ previousCaller));

}

*/

- and I’m now able to create a new user when logging on via LDAP with the log level set to DEBUG.

Of course, if anyone has any better suggestions, I’m all ears J

Cheers,

Mike

Michael White

Senior Developer

Business Applications and Integrations

T: (01786) 466877

E: michae...@stir.ac.uk

A: G5, Airthrey Castle, University of Stirling, Stirling, FK9 4LA

Humberto Blanco Castillo

unread,

Feb 20, 2020, 5:53:04 AM2/20/20

to DSpace Technical Support

michael , got any response for this issue? i have the same problem in dspace 6.3 xmlui

Mark H. Wood

unread,

Feb 20, 2020, 9:49:52 AM2/20/20

to DSpace Technical Support

I took a quick look at LDAPAuthentication.java. From the log
messages, it seems that execution reached the log.info() call at line
368. This flows down to the 'return' at line 370 BUT we are still in
a try{} with a finally{}, so it appears that this method will call
context.restoreAuthSystemState() twice before actually returning.
restoreAuthSystemState() catches the EmptyStackException and logs it.

The nested try{} blocks are a bit muddled. The method needs thorough
study and probably some re-organization.

There is quite a bit of code in Context#restoreAuthSystemState which
is only executed when debugging is enabled, around line 303 ff. I'm
not sure what it is for. This code *also* pops a stack without
checking for underflow, and in this case any resulting exception is
not caught, which may yield interesting results.

That's not a thorough analysis, but it is a start.

--
Mark H. Wood
Lead Technology Analyst

University Library
Indiana University - Purdue University Indianapolis
755 W. Michigan Street
Indianapolis, IN 46202
317-274-0749
www.ulib.iupui.edu

signature.asc

Ondrej Kosarko

unread,

Feb 24, 2020, 3:23:11 AM2/24/20

to DSpace Technical Support

Sounds a bit like https://jira.lyrasis.org/browse/DS-2505

Ondrej

From: "Mark H. Wood" <mwood...@gmail.com>
To: "DSpace Technical Support" <dspac...@googlegroups.com>
Sent: Thursday, 20 February, 2020 15:49:45
Subject: Re: [dspace-tech] Re: LDAPAuthentication - can't create ePerson at DEBUG

--
All messages to this mailing list should adhere to the DuraSpace Code of Conduct: https://duraspace.org/about/policies/code-of-conduct/
---
You received this message because you are subscribed to the Google Groups "DSpace Technical Support" group.
To unsubscribe from this group and stop receiving emails from it, send an email to dspace-tech...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/dspace-tech/20200220144945.GC1294%40IUPUI.Edu.

Reply all

Reply to author

Forward