This discussion is archived
5 Replies Latest reply: Nov 22, 2010 9:50 AM by user189677 RSS

DPS 6.3 incorrectly sharing connections?

user189677 Newbie
Currently Being Moderated
I am running DPS 6.3.1.1 against a set of DS 6.3 instances. I'm seeing cases where it appears DPS is using an open connection to the DS for multiple functions and creating scenarios where a failure occurs. For example, here is a snippet of my DPS access log:

[18/Nov/2010:12:58:17 -0500] conn=887212 op=24 msgId=26 - BIND dn="uid=dogbert,ou=People,ou=Special Accounts and Groups,o=n
y,c=us" method=128 version=3
[18/Nov/2010:12:58:17 -0500] conn=887212 op=24 msgId=26 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=dogbert,ou=people,
ou=special accounts and groups,o=ny,c=us"
[18/Nov/2010:12:58:17 -0500] conn=887212 op=25 msgId=27 - SRCH base="o=ny,c=us" scope=2 filter="(uid=stgcsstest)" attrs=ALL
[18/Nov/2010:12:58:17 -0500] conn=887212 op=25 msgId=27 - RESULT err=0 tag=101 nentries=1 etime=0
[18/Nov/2010:12:58:17 -0500] conn=887212 op=26 msgId=28 - SRCH base="uid=stgcsstest,ou=people,ou=nys office for technology,
ou=government,o=ny,c=us" scope=0 filter="(objectClass=*)" attrs="nylastlogin"
[18/Nov/2010:12:58:17 -0500] conn=887212 op=26 msgId=28 - RESULT err=0 tag=101 nentries=1 etime=0
[18/Nov/2010:12:58:17 -0500] conn=887212 op=27 msgId=29 - MOD dn="uid=stgcsstest,ou=People,ou=NYS Office for Technology,ou=
Government,o=ny,c=us"
[18/Nov/2010:12:58:17 -0500] conn=887212 op=27 msgId=29 - RESULT err=0 tag=103 nentries=0 etime=0 csn=4ce5770d000900030000
[18/Nov/2010:13:09:27 -0500] conn=887212 op=28 msgId=30 - SRCH base="" scope=0 filter="(objectClass=1.1)" attrs=ALL
[18/Nov/2010:13:09:27 -0500] conn=887212 op=28 msgId=30 - RESULT err=0 tag=101 nentries=0 etime=0
[18/Nov/2010:13:09:27 -0500] conn=887212 op=29 msgId=31 - MOD dn="uid=stgcsstest,ou=People,ou=NYS Office for Technology,ou=
Government,o=ny,c=us"
[18/Nov/2010:13:09:27 -0500] conn=887212 op=29 msgId=31 - RESULT err=0 tag=103 nentries=0 etime=0 csn=4ce579ab000400030000
[18/Nov/2010:13:13:54 -0500] conn=887212 op=30 msgId=32 - SRCH base="" scope=0 filter="(objectClass=1.1)" attrs=ALL
[18/Nov/2010:13:13:54 -0500] conn=887212 op=30 msgId=32 - RESULT err=0 tag=101 nentries=0 etime=0
[18/Nov/2010:13:13:54 -0500] conn=887212 op=31 msgId=33 - BIND dn="uid=usaivc,ou=People,ou=NYS Department of Labor,ou=Gover
nment,o=ny,c=us" method=128 version=3
[18/Nov/2010:13:13:54 -0500] conn=887212 op=31 msgId=33 - RESULT err=49 tag=97 nentries=0 etime=0
[18/Nov/2010:13:16:55 -0500] conn=887212 op=32 msgId=34 - SRCH base="" scope=0 filter="(objectClass=1.1)" attrs=ALL
[18/Nov/2010:13:16:55 -0500] conn=887212 op=32 msgId=34 - RESULT err=0 tag=101 nentries=0 etime=0
[18/Nov/2010:13:18:40 -0500] conn=887212 op=33 msgId=35 - MOD dn="uid=stgcsstest,ou=People,ou=NYS Office for Technology,ou=
Government,o=ny,c=us"
[18/Nov/2010:13:18:40 -0500] conn=887212 op=33 msgId=35 - RESULT err=50 tag=103 nentries=0 etime=0, Insufficient 'write' pr
ivilege to the 'nypreviouslogin' attribute of entry 'uid=stgcsstest,ou=people,ou=nys office for technology,ou=government,o=
ny,c=us'.
[18/Nov/2010:13:30:55 -0500] conn=887212 op=34 msgId=36 - SRCH base="" scope=0 filter="(objectClass=1.1)" attrs=ALL
[18/Nov/2010:13:30:55 -0500] conn=887212 op=34 msgId=36 - RESULT err=0 tag=101 nentries=0 etime=0
[18/Nov/2010:13:31:39 -0500] conn=887212 op=35 msgId=37 - MOD dn="uid=stgcsstest,ou=People,ou=NYS Office for Technology,ou=
Government,o=ny,c=us"
[18/Nov/2010:13:31:39 -0500] conn=887212 op=35 msgId=37 - RESULT err=50 tag=103 nentries=0 etime=0, Insufficient 'write' pr
ivilege to the 'nypreviouslogin' attribute of entry 'uid=stgcsstest,ou=people,ou=nys office for technology,ou=government,o=
ny,c=us'.

As you can see, I bind as dogbert and update the record for stgcsstest which is fine. Then at 13:13:54, I see a bind of another uid, usaivc, and then another MOD attempt. But since we are not bound as dogbert but this other user, the MOD that dogbert was supposed to do fails because it is being done as usaivc. I'm trying to figure out what setting I have wrong in DPS that is allowing it to insert other binds/work and make it still think that the original bind is in effect. Because I don't have an issue with other work going on in between, but then DPS should have resent a BIND for dogbert before sending the MOD.

Thanks in advance.
  • 1. Re: DPS 6.3 incorrectly sharing connections?
    user189677 Newbie
    Currently Being Moderated
    Sorry, I meant to say this is the snippet from the DS log. The DPS log shows 2 different connections trying to perform the client requests. One from dogbert and the other from usaivc.
  • 2. Re: DPS 6.3 incorrectly sharing connections?
    Sylvain Duloutre Pro
    Currently Being Moderated
    Hi,

    Could you post the DPS log sniplet please ?
    TIA

    -Sylvain
  • 3. Re: DPS 6.3 incorrectly sharing connections?
    user189677 Newbie
    Currently Being Moderated
    No problem. Just to help, the snippet from the DS is a node called pearl-stg-ldap-03. You'll need to know that because you'll see DPS bouncing around to the other DS instances on other machines. Here is the first snippet showing other work and then the usaivc BIND:

    [18/Nov/2010:13:04:22 -0500] - PROFILE - INFO - conn=628046 assigned to connection handler cn=default connection handler, cn=co
    nnection handlers, cn=config
    [18/Nov/2010:13:04:22 -0500] - CONNECT - INFO - conn=628046 client=10.64.168.147:42142 server=ds1af055-primary:636 protocol=LDA
    PS
    [18/Nov/2010:13:04:27 -0500] - OPERATION - INFO - conn=628046 op=0 msgid=2 SEARCH base="" scope=0 filter="(objectclass=1.1)" attr
    s="*"
    [18/Nov/2010:13:04:27 -0500] - PROFILE - INFO - conn=628046 assigned to connection handler cn=Tier 1 DPS Connection Handle,cn=c
    onnection handlers,cn=config
    [18/Nov/2010:13:04:27 -0500] - OPERATION - INFO - conn=628046 op=0 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:07:20 -0500] - OPERATION - INFO - conn=628046 op=1 msgid=3 SEARCH base="" scope=0 filter="(objectclass=1.1)" attr
    s="*"
    [18/Nov/2010:13:07:20 -0500] - OPERATION - INFO - conn=628046 op=1 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=2 msgid=4 SEARCH base="" scope=0 filter="(objectclass=1.1)" attr
    s="*"
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=2 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=3 BIND dn="uid=dogbert,ou=people,ou=special accounts and groups,
    o=ny,c=us" method="SIMPLE" version=3
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=3 BIND dn="uid=dogbert,ou=People,ou=Special Accounts and Groups,
    o=ny,c=us" method="SIMPLE" version=3 s_msgid=9 s_conn=pearl-stg-ldap-04:181239
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=3 BIND RESPONSE err=0 msg="" s_conn=pearl-stg-ldap-04:181239
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=3 BIND RESPONSE err=0 msg="" etime=0
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=4 msgid=6 SEARCH base="o=ny,c=us" scope=2 filter="(uid=stgcsstes
    t)" attrs="*"
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=4 SEARCH base="o=ny,c=us" scope=2 filter="(uid=stgcsstest)" attr
    s="*" s_msgid=6 s_conn=pearl-stg-ldap-02:181252
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=4 SEARCH RESPONSE err=0 msg="" nentries=1 s_conn=pearl-stg-ldap-
    02:181252
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=4 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=5 msgid=7 SEARCH base="uid=stgcsstest,ou=People,ou=NYS Office fo
    r Technology,ou=Government,o=ny,c=us" scope=0 filter="(objectClass=*)" attrs="nylastlogin "
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=5 SEARCH base="uid=stgcsstest,ou=people,ou=nys office for techno
    logy,ou=government,o=ny,c=us" scope=0 filter="(objectClass=*)" attrs="nylastlogin " s_msgid=10 s_conn=pearl-stg-ldap-04:181239
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=5 SEARCH RESPONSE err=0 msg="" nentries=1 s_conn=pearl-stg-ldap-
    04:181239
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=5 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=6 msgid=8 MODIFY dn="uid=stgcsstest,ou=People,ou=NYS Office for
    Technology,ou=Government,o=ny,c=us"
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=6 MODIFY dn="uid=stgcsstest,ou=People,ou=NYS Office for Technolo
    gy,ou=Government,o=ny,c=us" s_msgid=31 s_conn=pearl-stg-ldap-03:181187
    [18/Nov/2010:13:09:27 -0500] - SERVER_OP - INFO - conn=628046 op=6 MODIFY RESPONSE err=0 msg="" s_conn=pearl-stg-ldap-03:181187
    [18/Nov/2010:13:09:27 -0500] - OPERATION - INFO - conn=628046 op=6 MODIFY RESPONSE err=0 msg="" etime=0
    [18/Nov/2010:13:13:54 -0500] - OPERATION - INFO - conn=628046 op=7 msgid=9 SEARCH base="" scope=0 filter="(objectclass=1.1)" attr
    s="*"
    [18/Nov/2010:13:13:54 -0500] - OPERATION - INFO - conn=628046 op=7 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:13:54 -0500] - OPERATION - INFO - conn=628046 op=8 BIND dn="uid=usaivc,ou=people,ou=nys department of labor,ou=go
    vernment,o=ny,c=us" method="SIMPLE" version=3
    [18/Nov/2010:13:13:54 -0500] - SERVER_OP - INFO - conn=628046 op=8 BIND dn="uid=usaivc,ou=People,ou=NYS Department of Labor,ou=Go
    vernment,o=ny,c=us" method="SIMPLE" version=3 s_msgid=33 s_conn=pearl-stg-ldap-03:181187
    [18/Nov/2010:13:13:54 -0500] - SERVER_OP - INFO - conn=628046 op=8 BIND RESPONSE err=49 msg="" s_conn=pearl-stg-ldap-03:181187
    [18/Nov/2010:13:13:54 -0500] - OPERATION - INFO - conn=628046 op=8 BIND RESPONSE err=49 msg="" etime=0


    And now here is the snippet showing the MOD being sent:

    [18/Nov/2010:13:18:27 -0500] - PROFILE - INFO - conn=628303 assigned to connection handler cn=default connection handler, cn=co
    nnection handlers, cn=config
    [18/Nov/2010:13:18:27 -0500] - CONNECT - INFO - conn=628303 client=10.64.168.147:42369 server=ds1af055-primary:636 protocol=LDA
    PS
    [18/Nov/2010:13:18:28 -0500] - OPERATION - INFO - conn=628303 op=0 msgid=2 SEARCH base="" scope=0 filter="(objectclass=1.1)" attr
    s="*"
    [18/Nov/2010:13:18:28 -0500] - PROFILE - INFO - conn=628303 assigned to connection handler cn=Tier 1 DPS Connection Handle,cn=c
    onnection handlers,cn=config
    [18/Nov/2010:13:18:28 -0500] - OPERATION - INFO - conn=628303 op=0 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=1 BIND dn="uid=dogbert,ou=people,ou=special accounts and groups,
    o=ny,c=us" method="SIMPLE" version=3
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=1 BIND dn="uid=dogbert,ou=People,ou=Special Accounts and Groups,
    o=ny,c=us" method="SIMPLE" version=3 s_msgid=192 s_conn=pearl-stg-ldap-01:180524
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=1 BIND RESPONSE err=0 msg="" s_conn=pearl-stg-ldap-01:180524
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=1 BIND RESPONSE err=0 msg="" etime=0
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=2 msgid=4 SEARCH base="o=ny,c=us" scope=2 filter="(uid=stgcsstes
    t)" attrs="*"
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=2 SEARCH base="o=ny,c=us" scope=2 filter="(uid=stgcsstest)" attr
    s="*" s_msgid=7 s_conn=pearl-stg-ldap-02:181254
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=2 SEARCH RESPONSE err=0 msg="" nentries=1 s_conn=pearl-stg-ldap-
    02:181254
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=2 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=3 msgid=5 SEARCH base="uid=stgcsstest,ou=People,ou=NYS Office fo
    r Technology,ou=Government,o=ny,c=us" scope=0 filter="(objectClass=*)" attrs="nylastlogin "
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=3 SEARCH base="uid=stgcsstest,ou=people,ou=nys office for techno
    logy,ou=government,o=ny,c=us" scope=0 filter="(objectClass=*)" attrs="nylastlogin " s_msgid=45 s_conn=pearl-stg-ldap-04:179830
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=3 SEARCH RESPONSE err=0 msg="" nentries=1 s_conn=pearl-stg-ldap-
    04:179830
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=3 SEARCH RESPONSE err=0 msg="" nentries=1 etime=0
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=4 msgid=6 MODIFY dn="uid=stgcsstest,ou=People,ou=NYS Office for
    Technology,ou=Government,o=ny,c=us"
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=4 MODIFY dn="uid=stgcsstest,ou=People,ou=NYS Office for Technolo
    gy,ou=Government,o=ny,c=us" s_msgid=35 s_conn=pearl-stg-ldap-03:181187
    [18/Nov/2010:13:18:40 -0500] - SERVER_OP - INFO - conn=628303 op=4 MODIFY RESPONSE err=50 msg="Insufficient 'write' privilege to
    the 'nypreviouslogin' attribute of entry 'uid=stgcsstest,ou=people,ou=nys office for technology,ou=government,o=ny,c=us'.
    [18/Nov/2010:13:18:40 -0500] - OPERATION - INFO - conn=628303 op=4 MODIFY RESPONSE err=50 msg="Insufficient 'write' privilege to
    the 'nypreviouslogin' attribute of entry 'uid=stgcsstest,ou=people,ou=nys office for technology,ou=government,o=ny,c=us'.
  • 4. Re: DPS 6.3 incorrectly sharing connections?
    Sylvain Duloutre Pro
    Currently Being Moderated
    Thanks for the logs.

    It looks like you are hitting defect 6987726: The backend connection is "anonymized" because of the bind failure at 13:13:54 but DPS erroneously keep tracks of the last successful bind on that connection (as dogbert in your case) when it is returned to the connection pool. If by chance, that pooled connection is reused again later to server traffic with the same credentials, it does not rebind again, leading to (spurious) insufficient privilege errors (the operation is performed as anonymous).

    I woule recommand contacting the support team to get a relief.

    Hope this helps

    -Sylvain
  • 5. Re: DPS 6.3 incorrectly sharing connections?
    user189677 Newbie
    Currently Being Moderated
    Thanks Sylvain. I have opened a ticket. I'm just happy to know it's not something I did wrong.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points