Description Florian Best 2019-10-28 10:44:33 CET

(In reply to Felix Botner from Bug #49976 comment #5)
> last night the s4connector tests 170sync_ad_move_user
> 
> connector.log:
> 16.10.2019 02:23:08.152 LDAP (PROCESS): sync from ucs: [ user] [ modify]
> CN=umtwdfjf,CN=mtrvdflh,DC=autotest091c,DC=local
> 16.10.2019 02:23:09.216 LDAP (PROCESS): sync to ucs: [ user] [ move]
> u'uid=umtwdfjf,cn=users,dc=AutoTest091c,dc=local'
> 16.10.2019 02:23:09.217 LDAP (WARNING): move_in_ucs: cancel move, old and
> new dn are the same (u'uid=umtwdfjf,cn=users,dc=AutoTest091c,dc=local' to
> u'uid=umtwdfjf,cn=users,dc=AutoTest091c,dc=local')
> 16.10.2019 02:23:09.226 LDAP (PROCESS): sync to ucs: [ group] [ move]
> u'cn=tahedfjg,CN=mtrvdflh,dc=AutoTest091c,dc=local' 
> 
> test log:
>  +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
> (2019-10-16 02:22:49.373589) info 2019-10-16 02:22:49	 User umtwdfjf created
> (2019-10-16 02:22:49.751471) info 2019-10-16 02:22:49	 Group tahedfjg created
> (2019-10-16 02:22:50.144466) info 2019-10-16 02:22:50	 Object
> CN=tahedfjg,CN=groups,DC=AUTOTEST091C,DC=LOCAL modified
> (2019-10-16 02:22:50.190953) info 2019-10-16 02:22:50	 Waiting for full
> synchronisation (sleeping for 16 seconds)
> (2019-10-16 02:22:50.191662) info 2019-10-16 02:22:50	 Hint: You might want
> to decrease this value during debugging of the tests
> (2019-10-16 02:23:06.204621) info 2019-10-16 02:23:06	 EXECUTING: udm-test
> 'users/user' list | egrep '^DN:
> uid=umtwdfjf,cn=users,dc=AutoTest091c,dc=local$'
> (2019-10-16 02:23:06.375119) info 2019-10-16 02:23:06	 users/user object
> umtwdfjf exists
> (2019-10-16 02:23:06.824129) info 2019-10-16 02:23:06	 Object
> CN=umtwdfjf,CN=Users,DC=AUTOTEST091C,DC=LOCAL exists
> (2019-10-16 02:23:06.827885) info 2019-10-16 02:23:06	 EXECUTING: udm-test
> 'groups/group' list --filter "cn=tahedfjg" | egrep '^ *users: ' | sed 's/^
> *users: //'
> (2019-10-16 02:23:06.923966) info 2019-10-16 02:23:06	 EXECUTING: udm-test
> 'users/user' list --filter "uid=umtwdfjf" | egrep '^ *groups: ' | sed 's/^
> *groups: //'
> (2019-10-16 02:23:07.022604) info 2019-10-16 02:23:07	
> CN=tahedfjg,CN=groups,DC=AUTOTEST091C,DC=LOCAL:
> "CN=umtwdfjf,CN=Users,DC=AUTOTEST091C,DC=LOCAL" in "member" ??
> (2019-10-16 02:23:07.385300) info 2019-10-16 02:23:07	 Yes
> (2019-10-16 02:23:07.386089) info 2019-10-16 02:23:07	
> CN=umtwdfjf,CN=Users,DC=AUTOTEST091C,DC=LOCAL:
> "CN=tahedfjg,CN=groups,DC=AUTOTEST091C,DC=LOCAL" in "memberOf" ??
> (2019-10-16 02:23:07.764520) info 2019-10-16 02:23:07	 Yes
> (2019-10-16 02:23:07.765494) info 2019-10-16 02:23:07	
> +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
> (2019-10-16 02:23:07.766230) info 2019-10-16 02:23:07	 Move user and group
> (2019-10-16 02:23:07.767010) info 2019-10-16 02:23:07	
> +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
> (2019-10-16 02:23:08.148511) info 2019-10-16 02:23:08	 Object
> CN=umtwdfjf,CN=Users,DC=AUTOTEST091C,DC=LOCAL is now
> CN=umtwdfjf,CN=mtrvdflh,DC=AUTOTEST091C,DC=LOCAL
> (2019-10-16 02:23:08.553311) info 2019-10-16 02:23:08	 Object
> CN=tahedfjg,CN=groups,DC=AUTOTEST091C,DC=LOCAL is now
> CN=tahedfjg,CN=mtrvdflh,DC=AUTOTEST091C,DC=LOCAL
> (2019-10-16 02:23:08.597437) info 2019-10-16 02:23:08	 Waiting for full
> synchronisation (sleeping for 16 seconds)
> (2019-10-16 02:23:08.598106) info 2019-10-16 02:23:08	 Hint: You might want
> to decrease this value during debugging of the tests
> (2019-10-16 02:23:24.610499) info 2019-10-16 02:23:24	 EXECUTING: udm-test
> 'users/user' list | egrep '^DN:
> uid=umtwdfjf,cn=users,dc=AutoTest091c,dc=local$'
> (2019-10-16 02:23:24.721376) info 2019-10-16 02:23:24	 users/user object
> umtwdfjf exists
> (2019-10-16 02:23:24.722165) error 2019-10-16 02:23:24	 Expected operation
> to fail, but it succeeded
> (2019-10-16 02:23:24.722958) error 2019-10-16 02:23:24	 ****************
> Test failed above this line (110) ****************


Since ~ two weeks the test case 170sync_ad_move_user is failing, also in the released-errata test. It sometimes passes, so the test is flaky now.

https://jenkins.knut.univention.de:8181/job/UCS-4.4/job/UCS-4.4-2/job/S4Connector/16/cfg=master-only-released-errata-s4connector/testReport/52_s4connector/170sync_ad_move_user/master091c/
https://jenkins.knut.univention.de:8181/job/UCS-4.4/job/UCS-4.4-2/job/S4Connector/16/cfg=master-s4connector/testReport/52_s4connector/170sync_ad_move_user/master091c/

It might be caused by changes in http://errata.software-univention.de/ucs/4.4/306.html.
Especially Bug #50161 makes user creation faster.

Maybe just a missing wait call?