I downloaded OpenJDK source code, modified the com.sun.jndi.ldap.NamingEventNotifier JAVA class to set the control as NONCRITICAL instead of CRITICAL, and compiled the OpenJDK.
I reran my test, and as you expected, I no longer see "-get_ldapmessage_controls failed: 12 (Unavailable critical extension) (op=Abandon)" in the error log but the connection in CLOSE_WAIT state still persist after my JAVA application terminated.
Do you have any other recommendation? Do you recommend me to file a bug report for 389-ds?
Thanks,
David
On Fri, Feb 19, 2010 at 10:32 PM, Rich Megginson <rmeggins@xxxxxxxxxx> wrote:
Chun Tat David Chu wrote:
> Hi Rich,
>
> I very appreciate your help.Ok. Then I suppose OpenDS supports the control, or OpenDS does not
>
> >> Does the client send the Abandon request to OpenDS? If so, does
> OpenDS abandon the operation, or complain about the control?
> The client does send the abandon request to OpenDS according to the
> log file, and I think it processed the request peacefully. If you
> look at the 3 debug lines below. The first 2 lines showed when OpenDS
> received the abandon request, and the last line is when my app
> requested to disconnect. We'll pay attention on the 2nd line only.
>
> According to OpenDS Wiki
> (https://www.opends.org/wiki/page/DefinitionResultCode), result=118
> means "Canceled", and it is an indication that the server canceled
> processing on the request at the request of the client.
>
> [19/Feb/2010:18:57:00 -0500] ABANDON REQ conn=0 op=13 msgID=14
> idToAbandon=3
> [19/Feb/2010:18:57:00 -0500] ABANDON RES conn=0 op=13 msgID=14
> result=118 etime=1
> [19/Feb/2010:18:57:13 -0500] DISCONNECT conn=0 reason="Client Disconnect"
>
> I am still playing with the OpenDS debug settings to see if I can get
> more out of it. I also plan to download OpenJDK and modify JNDI code
> to set NONCRITICAL instead of CRITICAL and give that a try.
error if an unsupported control is sent with the Abandon operation.
> <mailto:rmeggins@xxxxxxxxxx>> wrote:
>
> Chun Tat David Chu wrote:
> > Hi Rich,
> >
> > Thank you for your quick response!
> >
> > I'll use the information you provided and file a bug on JNDI.
> >
> > Do you think this "UnavailableCriticalExtension" is the cause of why
> > connection not being closed successfully?
> Could be - if it attempts to Abandon the persistent search, but the
> Abandon request doesn't go through because of the control, the
> connection will remain open
> >
> > I am trying to figure out which end is the issue (Client or Server).
> > For testing purpose, I just downloaded OpenDS and installed it.
> I ran
> > the same test scenario for about 20 times, and I don't see any
> > CLOSE_WAIT connection on the OpenDS process.
> Does the client send the Abandon request to OpenDS? If so, does
> OpenDS
> abandon the operation, or complain about the control?
> >
> > - David
> >
> > On Fri, Feb 19, 2010 at 4:39 PM, Rich Megginson
> <rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>
> > <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>>> wrote:
> >
> > Chun Tat David Chu wrote:
> > > Hi Rich,
> > >
> > > That was quick response! Thank you!
> > >
> > > >> That seems like a bug in JNDI - can you file a bug?
> > > Yes I can do that but I'll need more information to backup
> my case.
> > > For example, which RFC stated that application shouldn't
> send a LDAP
> > > Abandon request for control that is marked as CRITICAL. I
> couldn't
> > > find that information in RFC 22551.
> > http://www.faqs.org/rfcs/rfc2251.html
> > The problem will happen with any request - if the client
> sends any
> > request (except Unbind) to the server, and attaches a
> control that is
> > marked as CRITICAL, and the server does not support that
> control, the
> > server returns unavailableCriticalExtension.
> >
> > http://www.ietf.org/rfc/rfc4511.txt - 4.1.11. Controls
> > "Specifically, the criticality field is applied as follows:
> >
> > - If the server does not recognize the control type,
> determines that
> > it is not appropriate for the operation, or is otherwise
> unwilling
> > to perform the operation with the control, and if the
> criticality
> > field is TRUE, the server MUST NOT perform the
> operation, and for
> > operations that have a response message, it MUST return
> with the
> > resultCode set to unavailableCriticalExtension."
> >
> > So the problem here is that
> > 1) JNDI is sending the Abandon request with a control not
> > supported for
> > the Abandon operation and/or not supported by the server
> > - solution - change the Abandon request to send only controls
> > supported
> > by the server (I'm not even sure why it is attempting to send a
> > control
> > with Abandon)
> > 2) JNDI is marking the control as CRITICAL
> > - solution - mark the control as non-critical
> > 3) JNDI does not know how to handle this standard result in
> a more
> > graceful manner
> > - solution - catch unavailableCriticalExtension and resubmit the
> > request
> > without the control or with the control marked non-critical
> > >
> > > >> Is there some way to verify that? Because the behavior you
> > > describe below would seem to suggest that not all
> operation results
> > > have been completely read by the client.
> > > :-( I am stuck on this part. I am not sure what is the
> best way to
> > > verify this because JNDI hides so much from me. I spend the
> > last two
> > > hours looking at tcpdump trying to see if there's any special
> > messages
> > > that was sent across but nothing pops up to me.
> > >
> > > >> Do you only see the problem when persistent search is used?
> > Do you
> > > see the problem when you don't use persistent search? This
> > would also
> > > lead me to believe the problem is that the client has not
> completed
> > > all operations successfully, and is therefore attempting to
> > submit an
> > > Abandon request to abandon those uncompleted operations.
> > > Yes, from my observation, this only happen with persistent
> > search. I
> > > tried different test scenarios such as 1) Create
> connection, do
> > > nothing, close connection and 2) Create connection, add
> > NamingListener
> > > (Persistent Search), remove NamingListener, close
> connection. I ran
> > > these two scenarios many times, and only when I add/remove
> > > NamingListener will trigger the CLOSE_WAIT connection on
> the slapd
> > > process.
> > >
> > > I did found something very interesting...
> > > If I put a sleep say 6 seconds after I established a LDAP
> connection
> > > and before I add a NamingListener then the connection will
> always
> > > clean-up successfully when the application exit. However,
> if I
> > don't
> > > put the sleep and add a NamingListener right after
> establishing the
> > > LDAP connection then when I my application exits, the
> slapd process
> > > will always end up with a CLOSE_WAIT connection. I tried
> this test
> > > scenario about 20 times and I always get the same result.
> Below is
> > > the code snippet and I'll re-attach the test case I use in
> this
> > e-mail.
> > >
> > > // Establish a context to LDAP.
> > > LDAP_CONTEXT =
> > > (EventDirContext) new InitialDirContext(
> > >
> > ldapEnvironmentHashtable).lookup(CONTEXT);
> > > Thread.sleep(6000);
> > > LDAP_CONTEXT.addNamingListener(
> > > SANDBOX_CONTEXT,
> EventContext.SUBTREE_SCOPE,
> > > myListener);
> > interesting
> > >
> > > Thanks for reading!
> > >
> > > - David
> > >
> > >
> > >
> > > On Fri, Feb 19, 2010 at 1:31 PM, Rich Megginson
> > <rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>
> <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>>
> > > <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>
> <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>>>> wrote:
> > >
> > > Chun Tat David Chu wrote:
> > > > Hi Rich,
> > > >
> > > > Thanks for your response. I very appreciate it.
> > > >
> > > > >> see if you can specify that no controls are to be
> sent
> > with the
> > > > Abandon request
> > > > I looked at the JNDI API documentation and I don't see
> > there's a
> > > way I
> > > > can do this. I did verify by reviewing the OpenJDK
> source
> > code that
> > > > it is setting the control as CRITICAL, and it is set
> in the
> > > > com.sun.jndi.ldap.NamingEventNotifier class.
> > > That seems like a bug in JNDI - can you file a bug?
> > > >
> > > > >> if you wait for all of the operations and results
> to be
> > read by
> > > > your app, JNDI might notice this and just do an Unbind
> > instead of an
> > > > Abandon.
> > > > The test application that I use done things in a
> sequential
> > > order so I
> > > > believe all the operations and results had already
> been read.
> > > Is there some way to verify that? Because the
> behavior you
> > describe
> > > below would seem to suggest that not all operation results
> > have been
> > > completely read by the client.
> > > >
> > > > I did more testings today using the same test I
> attached in my
> > > > original e-mail and found out that this problem
> happen very
> > > often but
> > > > sometime the connection does cleaned up correctly.
> Here's two
> > > > snippets of the errors log with "Connection management"
> > log level
> > > > enabled. The difference is that when it does work,
> I see the
> > > > "sasl_io_cleanup for connection" debug statement and it
> > appears that
> > > > slapd tries to release the connection and operation
> in all
> > cases
> > > > except often time it doesn't work (when persistent
> search
> > is used)
> > > Do you only see the problem when persistent search is
> used? Do
> > > you see
> > > the problem when you don't use persistent search? This
> > would also
> > > lead
> > > me to believe the problem is that the client has not
> > completed all
> > > operations successfully, and is therefore attempting to
> > submit an
> > > Abandon request to abandon those uncompleted operations.
> > > > and the connection get into a CLOSE_WAIT state.
> > > >
> > > > I will do more testing and poke more on the JAVA client.
> > > >
> > > > Thanks,
> > > >
> > > > David
> > > >
> > > > ###### WORKING LOG ######
> > > > [19/Feb/2010:13:12:49 -0500] - activity on 68r
> > > > [19/Feb/2010:13:12:49 -0500] - read activity on 68
> > > > [19/Feb/2010:13:12:49 -0500] - listener got signaled
> > > > [19/Feb/2010:13:12:49 -0500] - get_ldapmessage_controls
> > failed: 12
> > > > (Unavailable critical extension) (op=Abandon)
> > > > [19/Feb/2010:13:13:18 -0500] - activity on 68r
> > > > [19/Feb/2010:13:13:18 -0500] - read activity on 68
> > > > [19/Feb/2010:13:13:18 -0500] - conn 98 activity
> level = 3
> > > > [19/Feb/2010:13:13:18 -0500] - listener got signaled
> > > > [19/Feb/2010:13:13:18 -0500] Persistent Search - conn=98
> > op=2 The
> > > > operation has been abandoned
> > > > [19/Feb/2010:13:13:18 -0500] - conn 98 turbo rank =
> 3 out
> > of 5 conns
> > > > [19/Feb/2010:13:13:18 -0500] Persistent Search -
> conn=98 op=2
> > > > Releasing the connection and operation
> > > > [19/Feb/2010:13:13:18 -0500] - sasl_io_cleanup for
> > connection 0
> > > > [19/Feb/2010:13:13:18 -0500] - sasl_pop_IO_layer: no
> SASL
> > IO layer
> > > > [19/Feb/2010:13:13:18 -0500] - listener got signaled
> > > >
> > > > ###### NOT WORKING LOG ######
> > > > [19/Feb/2010:13:14:33 -0500] - activity on 68r
> > > > [19/Feb/2010:13:14:33 -0500] - read activity on 68
> > > > [19/Feb/2010:13:14:33 -0500] - conn 99 activity
> level = 2
> > > > [19/Feb/2010:13:14:33 -0500] - conn 99 turbo rank =
> 3 out
> > of 5 conns
> > > > [19/Feb/2010:13:14:34 -0500] - get_ldapmessage_controls
> > failed: 12
> > > > (Unavailable critical extension) (op=Abandon)
> > > > [19/Feb/2010:13:14:35 -0500] - listener got signaled
> > > > [19/Feb/2010:13:14:39 -0500] - activity on 68r
> > > > [19/Feb/2010:13:14:39 -0500] - read activity on 68
> > > > [19/Feb/2010:13:14:39 -0500] - conn 99 activity
> level = 2
> > > > [19/Feb/2010:13:14:39 -0500] - conn 99 turbo rank =
> 3 out
> > of 5 conns
> > > > [19/Feb/2010:13:14:39 -0500] Persistent Search - conn=99
> > op=2 The
> > > > operation has been abandoned
> > > > [19/Feb/2010:13:14:39 -0500] Persistent Search -
> conn=99 op=2
> > > > Releasing the connection and operation
> > > > [19/Feb/2010:13:14:39 -0500] - listener got signaled
> > > >
> > > >
> > > >
> > > > On Thu, Feb 18, 2010 at 8:14 PM, Rich Megginson
> > > <rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>
> <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>>
> > <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>
> <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>>>
> > > > <mailto:rmeggins@xxxxxxxxxx
> <mailto:rmeggins@xxxxxxxxxx> <mailto:rmeggins@xxxxxxxxxx
> <mailto:rmeggins@xxxxxxxxxx>>
> > <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>
> <mailto:rmeggins@xxxxxxxxxx <mailto:rmeggins@xxxxxxxxxx>>>>> wrote:
> > > >
> > > > Chun Tat David Chu wrote:
> > > > > Hi All,
> > > > >
> > > > > I am running 389 DS version 1.2.5, build number
> > > 2010.012.2034 on
> > > > RHEL 5.2.
> > > > >
> > > > > I have a problem that slapd didn't close a
> > connection and
> > > eventually
> > > > > get into a CLOSE_WAIT state after my JAVA
> > application exit.
> > > > >
> > > > > The scenario only happen when my application
> registers a
> > > > > NamingListener via the JAVA JNDI (Java Naming
> Directory
> > > > Interface). I
> > > > > believe the NamingListener is equivalent to the
> > Persistent
> > > Search.
> > > > > This problem doesn't exist if I don't use the JNDI
> > > NamingListener
> > > > > capability.
> > > > >
> > > > > From my understanding, I did everything
> correctly in my
> > > application.
> > > > > I create a context, add a listener, do some
> stuffs,
> > remove the
> > > > > listener and then close the context.
> > > > >
> > > > > One thing I notice is that in the slapd's
> error log,
> > I see the
> > > > > following...
> > > > > "-get_ldapmessage_controls failed: 12 (Unavailable
> > critical
> > > > extension)
> > > > > (op=Abandon)".
> > > > > This message prints out right after I remove the
> > listener
> > > and before
> > > > > my application closes the context.
> > > > >
> > > > > The closest bug report I found is this and it
> said the
> > > problem has
> > > > > been resolved.
> > > > > https://bugzilla.redhat.com/show_bug.cgi?id=450575
> > > > >
> > > > > At this point, I'm clueless. :-(
> > > > > Can someone help me or give me some recommendation
> > that I
> > > could try?
> > > > It looks as though the app is sending an LDAP
> Abandon
> > > request with
> > > > controls that are marked as critical, and the
> server does
> > > not support
> > > > them. This is standard LDAPv3 behavior. I'm
> not sure why
> > > it is using
> > > > Abandon, perhaps to Abandon any outstanding
> search or
> > other
> > > requests
> > > > that have not completed. Some things to check:
> > > > * see if you can specify that no controls are to
> be sent
> > > with the
> > > > Abandon request
> > > > * if you wait for all of the operations and
> results to be
> > > read by your
> > > > app, JNDI might notice this and just do an Unbind
> > instead of an
> > > > Abandon.
> > > > >
> > > > > I will attach my JAVA JNDI replicator along
> with this
> > > e-mail. You
> > > > > will need to modify 2-3 lines of code to get it
> > running in
> > > your
> > > > > environment. Search for "MODIFY ME" and that
> should
> > be the
> > > > lines that
> > > > > you need to modify.
> > > > >
> > > > > Thanks!
> > > > >
> > > > > David
> > > > >
> > > > >
> > > > >
> > > >
> > >
> >
> ------------------------------------------------------------------------
> > > > >
> > > > > --
> > > > > 389 users mailing list
> > > > > 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>>
> > > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>>>
> > > > >
> > https://admin.fedoraproject.org/mailman/listinfo/389-users
> > > >
> > > > --
> > > > 389 users mailing list
> > > > 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>>
> > > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>>>
> > > >
> https://admin.fedoraproject.org/mailman/listinfo/389-users
> > > >
> > > >
> > > >
> > >
> >
> ------------------------------------------------------------------------
> > > >
> > > > --
> > > > 389 users mailing list
> > > > 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>>
> > > >
> https://admin.fedoraproject.org/mailman/listinfo/389-users
> > >
> > > --
> > > 389 users mailing list
> > > 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>>
> > > https://admin.fedoraproject.org/mailman/listinfo/389-users
> > >
> > >
> > >
> >
> ------------------------------------------------------------------------
> > >
> > > --
> > > 389 users mailing list
> > > 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > > https://admin.fedoraproject.org/mailman/listinfo/389-users
> >
> > --
> > 389 users mailing list
> > 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>>
> > https://admin.fedoraproject.org/mailman/listinfo/389-users
> >
> >
> >
> ------------------------------------------------------------------------
> >
> > --
> > 389 users mailing list
> > 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> > https://admin.fedoraproject.org/mailman/listinfo/389-users
>
> --
> 389 users mailing list
> 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:389-users@xxxxxxxxxxxxxxxxxxxxxxx>
> https://admin.fedoraproject.org/mailman/listinfo/389-users
>
>
> ------------------------------------------------------------------------
>
> --
> 389 users mailing list
> 389-users@xxxxxxxxxxxxxxxxxxxxxxx
> https://admin.fedoraproject.org/mailman/listinfo/389-users
--
389 users mailing list
389-users@xxxxxxxxxxxxxxxxxxxxxxx
https://admin.fedoraproject.org/mailman/listinfo/389-users
-- 389 users mailing list 389-users@xxxxxxxxxxxxxxxxxxxxxxx https://admin.fedoraproject.org/mailman/listinfo/389-users
