Uploaded image for project: 'OpenAM'
  1. OpenAM
  2. OPENAM-10430

CTS fail-back does not work properly

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 13.5.2, 14.0.0
    • Fix Version/s: 13.5.2, 14.0.0
    • Component/s: CTS
    • Labels:
    • Environment:
      OpenAM 14.0.0-M13 Build 089887dedd (2017-January-17 11:17)
    • Support Ticket IDs:

      Description

      CTS fail-back does not work properly. Tested on CTS Active-Passive deployment. CTS1 is used as primary which handle all the session, CTS2 only replicate a sessions. If I turned off the CTS1, CTS2 take active role, what is correct, but if I turn on CTS1 again, CTS2 is still a active.

      Environment

      CTS fail-over is set: /Configure / Server Defaults / CTS / External Store Configuration / Connection String(s) = riso-centos7.test.forgerock.com:1389,riso-ubuntu14.test.forgerock.com:2389

      Steps to reproduce

      1.) Observe both CTS (OpenDJ) access logs and login as demo
      I used "tail -f ./access | grep -v SEARCH" (-v = all logs lines except SEARCH apperas, it is because primary CTS contains a lot off these logs)

      CTS 1 access logs
      [19/Jan/2017:16:13:45 +0000] ADD REQ conn=7 op=11 msgID=12 dn="coreTokenId=-5836625506790596528,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org"
      [19/Jan/2017:16:13:46 +0000] ADD RES conn=7 op=11 msgID=12 result=0 etime=11
      [19/Jan/2017:16:13:46 +0000] MODIFY REQ conn=-1 op=70 msgID=71 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:13:46 +0000] MODIFY RES conn=-1 op=70 msgID=71 result=0 etime=3
      
      CTS 2 access logs
      [19/Jan/2017:16:13:45 +0000] ADD REQ conn=-1 op=84 msgID=85 dn="coreTokenId=-5836625506790596528,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:13:45 +0000] ADD RES conn=-1 op=84 msgID=85 result=0 etime=11
      [19/Jan/2017:16:13:46 +0000] MODIFY REQ conn=-1 op=87 msgID=88 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:13:46 +0000] MODIFY RES conn=-1 op=87 msgID=88 result=0 etime=2
      

      As you can see CTS 2 logs contains "type=synchronization" on ADD REQ what means replication session, CTS1 does not contain it, because session was created using this CTS1 (Active CTS)

      2.) Turn off CTS 1 (primary)
      Fail-over to CTS 2, you can login, to see that no type=sync appears in CTS2 access logs, because CTS 2 become Active (primary), also access log contains a lot of SEARCH REQ/RES

      3.) Turn on CTS 1 and login with user, clear cookies and login more times.

      Observed result

      You can see that sessions are created randomly in CTSs (sometimes in CTS1, sometimes in CTS2)

      CTS 1 access logs
      [19/Jan/2017:16:51:54 +0000] ADD REQ conn=-1 op=145 msgID=146 dn="coreTokenId=-7662943262912390295,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:51:54 +0000] ADD RES conn=-1 op=145 msgID=146 result=0 etime=15
      [19/Jan/2017:16:51:54 +0000] MODIFY REQ conn=-1 op=148 msgID=149 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:51:54 +0000] MODIFY RES conn=-1 op=148 msgID=149 result=0 etime=1
      [19/Jan/2017:16:51:57 +0000] ADD REQ conn=21 op=34 msgID=35 dn="coreTokenId=6145272126953479445,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org"
      [19/Jan/2017:16:51:57 +0000] ADD RES conn=21 op=34 msgID=35 result=0 etime=4
      [19/Jan/2017:16:51:57 +0000] MODIFY REQ conn=-1 op=150 msgID=151 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:51:57 +0000] MODIFY RES conn=-1 op=150 msgID=151 result=0 etime=1
      [19/Jan/2017:16:51:59 +0000] ADD REQ conn=25 op=31 msgID=32 dn="coreTokenId=4641497190108545160,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org"
      [19/Jan/2017:16:51:59 +0000] ADD RES conn=25 op=31 msgID=32 result=0 etime=5
      [19/Jan/2017:16:52:00 +0000] MODIFY REQ conn=-1 op=152 msgID=153 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:00 +0000] MODIFY RES conn=-1 op=152 msgID=153 result=0 etime=2
      [19/Jan/2017:16:52:01 +0000] ADD REQ conn=-1 op=153 msgID=154 dn="coreTokenId=-8015683590482795621,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:01 +0000] ADD RES conn=-1 op=153 msgID=154 result=0 etime=9
      [19/Jan/2017:16:52:02 +0000] MODIFY REQ conn=-1 op=156 msgID=157 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:02 +0000] MODIFY RES conn=-1 op=156 msgID=157 result=0 etime=3
      [19/Jan/2017:16:52:03 +0000] ADD REQ conn=23 op=37 msgID=38 dn="coreTokenId=5390003959044315118,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org"
      [19/Jan/2017:16:52:03 +0000] ADD RES conn=23 op=37 msgID=38 result=0 etime=8
      [19/Jan/2017:16:52:04 +0000] MODIFY REQ conn=-1 op=158 msgID=159 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:04 +0000] MODIFY RES conn=-1 op=158 msgID=159 result=0 etime=2
      [19/Jan/2017:16:52:06 +0000] ADD REQ conn=-1 op=159 msgID=160 dn="coreTokenId=2497509113675059550,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:06 +0000] ADD RES conn=-1 op=159 msgID=160 result=0 etime=7
      [19/Jan/2017:16:52:06 +0000] MODIFY REQ conn=-1 op=162 msgID=163 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:06 +0000] MODIFY RES conn=-1 op=162 msgID=163 result=0 etime=2
      
      CTS 2 access logs
      [19/Jan/2017:16:51:53 +0000] ADD REQ conn=16 op=49 msgID=50 dn="coreTokenId=-7662943262912390295,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org"
      [19/Jan/2017:16:51:53 +0000] ADD RES conn=16 op=49 msgID=50 result=0 etime=9
      [19/Jan/2017:16:51:54 +0000] MODIFY REQ conn=-1 op=184 msgID=185 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:51:54 +0000] MODIFY RES conn=-1 op=184 msgID=185 result=0 etime=2
      [19/Jan/2017:16:51:57 +0000] ADD REQ conn=-1 op=185 msgID=186 dn="coreTokenId=6145272126953479445,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:51:57 +0000] ADD RES conn=-1 op=185 msgID=186 result=0 etime=6
      [19/Jan/2017:16:51:58 +0000] MODIFY REQ conn=-1 op=188 msgID=189 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:51:58 +0000] MODIFY RES conn=-1 op=188 msgID=189 result=0 etime=2
      [19/Jan/2017:16:51:59 +0000] ADD REQ conn=-1 op=189 msgID=190 dn="coreTokenId=4641497190108545160,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:51:59 +0000] ADD RES conn=-1 op=189 msgID=190 result=0 etime=7
      [19/Jan/2017:16:52:00 +0000] MODIFY REQ conn=-1 op=192 msgID=193 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:00 +0000] MODIFY RES conn=-1 op=192 msgID=193 result=0 etime=2
      [19/Jan/2017:16:52:01 +0000] ADD REQ conn=14 op=49 msgID=50 dn="coreTokenId=-8015683590482795621,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org"
      [19/Jan/2017:16:52:01 +0000] ADD RES conn=14 op=49 msgID=50 result=0 etime=12
      [19/Jan/2017:16:52:02 +0000] MODIFY REQ conn=-1 op=194 msgID=195 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:02 +0000] MODIFY RES conn=-1 op=194 msgID=195 result=0 etime=1
      [19/Jan/2017:16:52:03 +0000] ADD REQ conn=-1 op=195 msgID=196 dn="coreTokenId=5390003959044315118,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:03 +0000] ADD RES conn=-1 op=195 msgID=196 result=0 etime=6
      [19/Jan/2017:16:52:04 +0000] MODIFY REQ conn=-1 op=198 msgID=199 dn="dc=cts,dc=forgerock,dc=org" type=synchronization
      [19/Jan/2017:16:52:04 +0000] MODIFY RES conn=-1 op=198 msgID=199 result=0 etime=2
      [19/Jan/2017:16:52:06 +0000] ADD REQ conn=0 op=105 msgID=106 dn="coreTokenId=2497509113675059550,ou=famrecords,ou=openam-session,ou=tokens,dc=cts,dc=forgerock,dc=org"
      [19/Jan/2017:16:52:06 +0000] ADD RES conn=0 op=105 msgID=106 result=0 etime=7
      

      Also the SEARCH requests are still appears on CTS2 after fail-back. See example of these requests

      [19/Jan/2017:16:35:01 +0000] SEARCH REQ conn=12 op=75 msgID=76 base="" scope=base filter="(objectClass=*)" attrs="1.1"
      [19/Jan/2017:16:35:01 +0000] SEARCH RES conn=12 op=75 msgID=76 result=0 nentries=1 etime=1
      [19/Jan/2017:16:35:02 +0000] SEARCH REQ conn=4 op=83 msgID=84 base="" scope=base filter="(objectClass=*)" attrs="1.1"
      [19/Jan/2017:16:35:02 +0000] SEARCH RES conn=4 op=83 msgID=84 result=0 nentries=1 etime=1
      [19/Jan/2017:16:35:04 +0000] SEARCH REQ conn=8 op=72 msgID=73 base="" scope=base filter="(objectClass=*)" attrs="1.1"
      [19/Jan/2017:16:35:04 +0000] SEARCH REQ conn=9 op=72 msgID=73 base="" scope=base filter="(objectClass=*)" attrs="1.1"
      [19/Jan/2017:16:35:04 +0000] SEARCH RES conn=9 op=72 msgID=73 result=0 nentries=1 etime=1
      [19/Jan/2017:16:35:04 +0000] SEARCH RES conn=8 op=72 msgID=73 result=0 nentries=1 etime=1
      [19/Jan/2017:16:35:04 +0000] SEARCH REQ conn=10 op=72 msgID=73 base="" scope=base filter="(objectClass=*)" attrs="1.1"
      [19/Jan/2017:16:35:04 +0000] SEARCH RES conn=10 op=72 msgID=73 result=0 nentries=1 etime=1
      [19/Jan/2017:16:35:05 +0000] SEARCH REQ conn=11 op=74 msgID=75 base="" scope=base filter="(objectClass=*)" attrs="1.1"
      [19/Jan/2017:16:35:05 +0000] SEARCH RES conn=11 op=74 msgID=75 result=0 nentries=1 etime=1
      [19/Jan/2017:16:35:08 +0000] SEARCH REQ conn=1 op=71 msgID=72 base="" scope=base filter="(objectClass=*)" attrs="1.1"
      

      Expected

      All sessions should be created on primary CTS1 and SEARCH REQ/RES should not be on secondary CTS after fail-back

        Attachments

          Activity

            People

            • Assignee:
              ram.anaswara Ramnishath Anaswara [X] (Inactive)
              Reporter:
              richard.hruza Richard Hruza
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: