bug: 400 error when list groups members

[christiangda]

This issue come from a comment in issue #62

Hi there!
This bug appeared again for us; we're using last version (0.0.13).
We're syncing three groups, and one of them have more than 100 users (137 right now).
I deleted the state to force a clean run of the sync app, but it still returns that error (and doesn't recreate the state.json).
Thanks a lot!

Originally posted by @snavarro-factorial in #62 (comment)

[christiangda]

more information here: #62 (comment)

[snavarro-factorial]

Hi!
I'll put here again the command and the "full" log of it and what it does:

Info:

SysAdmin: 10 users
Developers: 137 users
Data: 5 users

Command:

./idpscim \
--aws-s3-bucket-key "cli-state.json" \
--aws-s3-bucket-name scim-test.xxxxx \
--aws-scim-access-token 'xxxxxxx' \
--aws-scim-endpoint https://scim.eu-central-1.amazonaws.com/xxxxxx/scim/v2/ \
--config-file ".idpscim.yaml" \
--gws-groups-filter 'name=SysAdmin' \
--gws-groups-filter 'name=Developers' \
--gws-groups-filter 'name=Data' \
--gws-service-account-file credentials.json \
--gws-user-email xxxxxxxx \
--log-format text \
--log-level info \
--sync-method groups

Output:

INFO[0000] starting sync groups                          codeVersion=v0.0.13
INFO[0000] getting identity provider data                group_filter="[name=SysAdmin name=Developers name=Data]"
INFO[0045] getting state data
WARN[0045] no state file found in the state repository, creating a new one
WARN[0045] syncing from scim service, first time syncing
WARN[0045] reconciling the SCIM data with the Identity Provider data
INFO[0045] getting SCIM Groups
INFO[0045] reconciling groups                            idp=3 scim=3
INFO[0045] no groups to be create
INFO[0045] no groups to be updated
INFO[0045] no groups to be deleted
INFO[0045] getting SCIM Users
INFO[0045] reconciling users                             idp=137 scim=50
WARN[0045] creating users                                quantity=87
WARN[0045] creating user                                 email=xxxx user="xxxx"
WARN[0046] aws CreateOrGetUser: user already exists, trying to get the user information  user=xxxx
[...] (same two lines for each user, but only for 86 users instead of all 137 for Developers group)
WARN[0062] creating user                                 email=xxxx user="xxxx"
WARN[0062] aws CreateOrGetUser: user already exists, trying to get the user information  user=xxxx
INFO[0062] no users to be updated
INFO[0062] no users to be removed
INFO[0062] getting SCIM Groups Members
Error: cannot sync groups and their members: error doing the first sync: error getting groups members from the SCIM service: scim: error listing groups: statusCode: 400,  errCode: 400 Bad Request, errMsg: {"schema":["urn:ietf:params:scim:api:messages:2.0:Error"],"schemas":["urn:ietf:params:scim:api:messages:2.0:Error"],"detail":"Request is unparsable, syntactically incorrect, or violates schema.","status":"400","exceptionRequestId":"92f45a50-8c57-486b-88db-76f58fcffb3a","timeStamp":"2022-07-18 15:14:53.838"}

Result:
Users seem to be created (there are some cases in which some user email was changed in Google and those aren't recreated until I delete the previous user, but I don't care about that now).
I didn't check if groups are being created too.
What I'm sure, is that users don't get added to their groups.

Thanks!

[christiangda]

@snavarro-factorial thank you very much for your detailed information, I have an idea of the problem, but I need your help to understand better what is happening.

The problem is here

idp-scim-sync/internal/scim/scim.go

Line 602 in caa2271

f := fmt.Sprintf("id eq %q and members eq %q", group.SCIMID, user.SCIMID)

I don't know why after getting the users and groups from the SCIM side, it looks like some of them have the SCIMID empty

So, I added new trace logs in a branch fix-issue#75 to get much information from you, so what I need:

1. clone the project in the main branch and then do check out of this branch [fix-issue#75] (https://github.com/slashdevops/idp-scim-sync/tree/fix-issue%2375) --> git checkout fix-issue#75
2. execute to make command in your local environment
3. execute build/idpscim program with your parameters but set --log-level trace
4. bring me more information about which user or group has the SCIMID empty and why?

NOTE: the idea is to have all the information you can provide to me about your problem because to fix this I need to replicate more or less your case in my idp and scim environment

Example of how to call the built program:

./build/idpscim \
--aws-s3-bucket-key "cli-state.json" \
--aws-s3-bucket-name scim-test.xxxxx \
--aws-scim-access-token 'xxxxxxx' \
--aws-scim-endpoint https://scim.eu-central-1.amazonaws.com/xxxxxx/scim/v2/ \
--config-file ".idpscim.yaml" \
--gws-groups-filter 'name=SysAdmin' \
--gws-groups-filter 'name=Developers' \
--gws-groups-filter 'name=Data' \
--gws-service-account-file credentials.json \
--gws-user-email xxxxxxxx \
--log-format text \
--log-level trace \
--sync-method groups

NOTE: also this information is important for me

Users seem to be created (there are some cases in which some user email was changed in Google and those aren't recreated until I delete the previous user, but I don't care about that now).

Why?

because if you change the user email, for the program this means you delete the oldest one and you are creating a new user. So what the program needs to do is delete the oldest one and create a new one with the new email

[snavarro-factorial]

Thanks for all the help!

I've done as you said, and the trace in that particular point is as follows:

time="2022-07-20T15:33:36+02:00" level=info msg="no users to be updated"
time="2022-07-20T15:33:36+02:00" level=info msg="no users to be removed"
time="2022-07-20T15:33:36+02:00" level=info msg="getting SCIM Groups Members"
time="2022-07-20T15:33:36+02:00" level=trace msg="scim GetGroupsMembersBruteForce: checking if user is member of group" IPID=118391303205636094465 SCIMID= group=SysAdmin user=TEST_EMAIL
time="2022-07-20T15:33:36+02:00" level=trace msg="aws newRequest: request" body="<nil>" method=GET path=/kE3934e0444-9ba8-41e7-b468-2fecf5b4fa22/scim/v2/Groups query="filter=id+eq+%22996716d1ce-e9fd9c92-6875-443d-8961-3111eec8edab%22+and+members+eq+%22%22" url="https://scim.eu-central-1.amazonaws.com/kE3934e0444-9ba8-41e7-b468-2fecf5b4fa22/scim/v2/Groups?filter=id+eq+%22996716d1ce-e9fd9c92-6875-443d-8961-3111eec8edab%22+and+members+eq+%22%22"
time="2022-07-20T15:33:36+02:00" level=trace msg="aws checkHTTPResponse: body: {\"schema\":[\"urn:ietf:params:scim:api:messages:2.0:Error\"],\"schemas\":[\"urn:ietf:params:scim:api:messages:2.0:Error\"],\"detail\":\"Request is unparsable, syntactically incorrect, or violates schema.\",\"status\":\"400\",\"exceptionRequestId\":\"0211c102-938d-46e1-aa6f-9dcffdfbfe5b\",\"timeStamp\":\"2022-07-20 13:33:36.886\"}\n" status="400 Bad Request" statusCode=400
Error: cannot sync groups and their members: error doing the first sync: error getting groups members from the SCIM service: scim: error listing groups: statusCode: 400,  errCode: 400 Bad Request, errMsg: {"schema":["urn:ietf:params:scim:api:messages:2.0:Error"],"schemas":["urn:ietf:params:scim:api:messages:2.0:Error"],"detail":"Request is unparsable, syntactically incorrect, or violates schema.","status":"400","exceptionRequestId":"0211c102-938d-46e1-aa6f-9dcffdfbfe5b","timeStamp":"2022-07-20 13:33:36.886"}

It's actually true that SCIMID is empty, so I went to the trace where it retrieves that user info, and this is what I've got (I replaced email to TEST_EMAIL and username to TEST_USERNAME):

time="2022-07-20T15:33:19+02:00" level=trace msg="creating user" email=TEST_EMAIL ipdid=118391303205636094465 user="TEST_USER"
time="2022-07-20T15:33:19+02:00" level=warning msg="creating user" email=TEST_EMAIL user="TEST_USER"
time="2022-07-20T15:33:19+02:00" level=trace msg="aws newRequest: request" body="{ 118391303205636094465 {  } [] TEST_EMAIL {TEST_USER } TEST_USER   true [0x14000564c60] []}" method=POST path=/kE3934e0444-9ba8-41e7-b468-2fecf5b4fa22/scim/v2/Users query= url="https://scim.eu-central-1.amazonaws.com/kE3934e0444-9ba8-41e7-b468-2fecf5b4fa22/scim/v2/Users"
time="2022-07-20T15:33:19+02:00" level=trace msg="aws checkHTTPResponse: body: {\"schema\":[\"urn:ietf:params:scim:api:messages:2.0:Error\"],\"schemas\":[\"urn:ietf:params:scim:api:messages:2.0:Error\"],\"detail\":\"Refused to create a new, duplicate resource.\",\"status\":\"409\",\"exceptionRequestId\":\"be36cad9-9984-418c-864b-d5c946bb7d33\",\"timeStamp\":\"2022-07-20 13:33:19.84\"}\n" status="409 Conflict" statusCode=409
time="2022-07-20T15:33:19+02:00" level=warning msg="aws CreateOrGetUser: user already exists, trying to get the user information" user=TEST_EMAIL
time="2022-07-20T15:33:19+02:00" level=trace msg="aws newRequest: request" body="<nil>" method=GET path=/kE3934e0444-9ba8-41e7-b468-2fecf5b4fa22/scim/v2/Users query="filter=userName+eq+%22TEST_EMAIL%22" url="https://scim.eu-central-1.amazonaws.com/kE3934e0444-9ba8-41e7-b468-2fecf5b4fa22/scim/v2/Users?filter=userName+eq+%22TEST_EMAIL%22"
time="2022-07-20T15:33:19+02:00" level=trace msg="aws CreateOrGetUser: obtained user information" active=false externalId= id= user=TEST_EMAIL

In any case, I'll attach the "full" log (I removed all the "creatinguser" lines regarding other users and left only the one with that user that fails; all lines removed were replaced by a [...]).
log.txt

I hope this helps! Thanks again!

[snavarro-factorial]

Extra info:
That user without SCIMID is the first one that appears on the log (crashing after it), so I presume that none of them have that SCIMID either. Could it be something provided by Google that now changed? (just throwing ideas)

[christiangda]

thank you very much @snavarro-factorial , now I have a better idea of the problem.

Looks like the AWS SCIM API changes as you commented, our problem is here

time="2022-07-20T15:33:19+02:00" level=trace msg="aws CreateOrGetUser: obtained user information" active=false externalId= id= user=TEST_EMAIL

ones the user is created, I don't know why retrieving information the id is empty, and this is why after when trying to find the groups fail

line of code where start the problem:

idp-scim-sync/internal/scim/scim.go

Line 296 in caa2271

r, err := s.scim.CreateOrGetUser(ctx, userRequest)

I have a question @snavarro-factorial is the user deactivated? because the answer from AWS API say that the user is not active, this is true?

time="2022-07-20T15:33:19+02:00" level=trace msg="aws CreateOrGetUser: obtained user information" active=false externalId= id= user=TEST_EMAIL

lines of code involved:

idp-scim-sync/pkg/aws/scim.go

Line 238 in caa2271

func (s *SCIMService) CreateOrGetUser(ctx context.Context, usr *CreateUserRequest) (*CreateUserResponse, error) {

idp-scim-sync/pkg/aws/scim.go

Line 288 in caa2271

response, err := s.GetUserByUserName(ctx, usr.UserName)

idp-scim-sync/pkg/aws/scim.go

Line 295 in caa2271

"id": response.ID,

I think the id is empty because this is not active, and I didn't consider this scenario and now I will.

please let me know if this is true

[christiangda]

also @snavarro-factorial please fetch the latest change I did to the branch fix-issue#75 and build and run the code again.

I added a new trace log to see the raw data coming from the AWS SCIM API when I retrieve the user information.

idp-scim-sync/pkg/aws/scim.go

Line 406 in 8dcb637

if resp.StatusCode == http.StatusOK && log.GetLevel() == log.TraceLevel {

Then please share the relevant information you got.

[snavarro-factorial]

Hi there!
Nope, that user is "Active" in Google :(
And attached the log with the latest branch changes (obfuscated with same TEST_USERNAME and TEST_EMAIL placeholders). This time is the actual full log, I didn't trim anything because for some reason it didn't try to create all users again, but it fails with the same user as before (don't know if it'll fail with other users since it stops there).
Thanks a lot!
log.txt

[snavarro-factorial]

Hello!
A coworker that knew about Go checked the code and with some breakpoints and tests we could make it work in the end; it seemed to be related to leftovers of accounts that had their email changed and the sync app couldn't delete and recreate them.
Probably for these cases it'll be nice a parameter to "force recreate everything"? Because until now I just had to delete the state and then re-run it, but there were many errors on AWS SSO users so it got stuck.

There was also a bug on a if/else block, tried to find it again with no avail, but it was something that only occured when you used "trace" log level, since it makes the code go into that if/else, it reads some file and closes it, and when it goes out of the if/else block it tries to read it again and that forced the code to close with an EOF.

Thanks a lot!
P.S.: Issue can be closed, I suppose 👀

[christiangda]

hi @snavarro-factorial I think I fixed the problem you are having

After several code changes and improvements, also I detected at least 4 bugs already fixed and new code is merged in the main branch.

I'm waiting for your confirmation of the bug mitigation to close this ticket and create a new release.

Could you test again using the new code from the main branch? set the in info level and let me know how it is working for you.

NOTE:

1. As the documentation say, the user email and the groups name are basically the primary keys, if you change some of them, a new user and/or group will be created and the older ones deleted.
2. The bugs fixed in the main branch were related to the case you mention.

[christiangda]

fixed in release #v0.0.12

[snavarro-factorial]

Sorry, since I have no error already because I synced "from scratch" I can't test it properly :(
In any case, I'll deploy the new version and open an issue in case I find anything on it, thanks!

[christiangda]

hi @snavarro-factorial thank you very much, don't worry, I understand.

Also, I would like to let you know that now this is fixed and tested in v0.0.14.

Now you can change the primary keys of the entities without any problem.

Users -> email
Groups -> Name