Description Felix Botner 2022-07-22 12:52:28 CEST

I have a ID Broker environment with school authorities. This works so far.

But for some test i want to resync a complete school, that is why i removed the ou on the provisioning server in the broker env:

-> udm container/ou remove --dn ou=auth1-school1,dc=idbroker,dc=local

Now i just create one student on the "auth1" school server in school "school1".

Occasionally the following happens.

id connector on auth1 wants to create user -> create school, but fails.

2022-07-22 12:21:57 INFO  [IDBrokerPerSAUserDispatcher(auth1).create_school_if_missing:104] Creating school 'school1'...
2022-07-22 12:22:00 ERROR [OutQueue(auth1).handle:573] Error HTTP 400 (Bad Request) creating School {'display_name': 'school1',
 'id': 'ff992e6a-6f90-103c-9cd1-573a05177ae6',
 'name': 'school1'}.
Traceback (most recent call last):
  File "/var/lib/univention-appcenter/apps/ucsschool-id-connector/conf/plugins/packages/idbroker/id_broker_client.py", line 332, in _create
    new_obj = await self._request("post", **kwargs)
  File "/var/lib/univention-appcenter/apps/ucsschool-id-connector/conf/plugins/packages/idbroker/id_broker_client.py", line 458, in _request
    res = await meth(*args, **kwargs)
  File "/var/lib/univention-appcenter/apps/ucsschool-id-connector/conf/plugins/packages/idbroker/provisioning_api/api_client.py", line 192, in __call_api
    raise e
  File "/var/lib/univention-appcenter/apps/ucsschool-id-connector/conf/plugins/packages/idbroker/provisioning_api/api_client.py", line 185, in __call_api
    response_data = await self.request(
  File "/var/lib/univention-appcenter/apps/ucsschool-id-connector/conf/plugins/packages/idbroker/provisioning_api/rest.py", line 219, in POST
    return (await self.request("POST", url,
  File "/var/lib/univention-appcenter/apps/ucsschool-id-connector/conf/plugins/packages/idbroker/provisioning_api/rest.py", line 176, in request
    raise ApiException(http_resp=r)
idbroker.provisioning_api.exceptions.ApiException: (400)
Reason: Bad Request
HTTP response headers: <CIMultiDictProxy('Date': 'Fri, 22 Jul 2022 10:21:57 GMT', 'Server': 'uvicorn', 'Content-Length': '24', 'Content-Type': 'application/json', 'Via': '1.1 provisioning1.broker.local', 'Connection': 'close')>
HTTP response body: {"detail":"Bad Request"}

On the provisioning server i see

2022-07-22 12:21:58 DEBUG session.request:189  POST 'https://provisioning1.broker.local/ucsschool/kelvin/token' (**{'headers': {'Content-Type': 'application/x-www-form-urlencoded'}, 'data': {'username': 'ucssc-25231611$', 'password': '**********'}, 'timeout': 120}) -> 200 'OK'
2022-07-22 12:22:00 DEBUG _client._send_single_request:1728  HTTP Request: POST https://provisioning1.broker.local/ucsschool/kelvin/v1/schools/ "HTTP/1.1 400 Bad Request"
2022-07-22 12:22:00 DEBUG session.request:189  POST 'https://provisioning1.broker.local/ucsschool/kelvin/v1/schools/' (**{'json': {'name': 'auth1-school1', 'udm_properties': {'ucsschoolRecordUID': 'ff992e6a-6f90-103c-9cd1-573a05177ae6', 'ucsschoolSourceUID': 'auth1', 'idBrokerPseudonym0001': 'f63b3912f9c3f2e8e30f62d921b3838f62b154d447f773facfea42ee5e890430e72bc9b04e010a018b41dfeda0e6b80e756ff44d05b6cb28909193cead1ccbae', 'idBrokerPseudonym0002': 'aff03e551862fe706b0cda3cc5c9efe373349f26b0dfe36daa3023ddcd57817d1e2890213485c56700cea9c6cccfdac148df209e2440751550acb1131bee15e6'}, 'display_name': 'school1', 'educational_servers': ['dc-2442385495'], 'class_share_file_server': 'dc-2442385495', 'home_share_file_server': 'dc-2442385495'}, 'headers': {'accept': 'application/json', 'Authorization': '**********', 'Content-Type': 'application/json'}, 'timeout': 120}) -> 400 'Bad Request' (Failed to create school 'auth1-school1': Session is closed)
2022-07-22 12:22:00 INFO  h11_impl.send:431  172.17.42.1:47178 - "POST /ucsschool/apis/provisioning/v1/auth1/schools HTTP/1.1" 400


in the provisioning API and

2022-07-22 12:21:59 INFO  Creating Container(name='mitarbeiter', school='auth1-school1', dn='cn=mitarbeiter,cn=groups,ou=auth1-school1,dc=idbroker,dc=local', old_dn='cn=mitarbeiter,ou=auth1-school1,dc=idbroker,dc=local')
2022-07-22 12:21:59 INFO  Creating Container(name='dhcp', school='auth1-school1', dn='cn=dhcp,ou=auth1-school1,dc=idbroker,dc=local')
2022-07-22 12:21:59 INFO  Creating Container(name='policies', school='auth1-school1', dn='cn=policies,ou=auth1-school1,dc=idbroker,dc=local')
2022-07-22 12:21:59 INFO  Creating Container(name='shares', school='auth1-school1', dn='cn=shares,ou=auth1-school1,dc=idbroker,dc=local')
2022-07-22 12:21:59 INFO  Creating Container(name='klassen', school='auth1-school1', dn='cn=klassen,cn=shares,ou=auth1-school1,dc=idbroker,dc=local', old_dn='cn=klassen,ou=auth1-school1,dc=idbroker,dc=local')
2022-07-22 12:21:59 INFO  establishing new connection with retry_max=11
2022-07-22 12:21:59 INFO  bind binddn=cn=admin,dc=idbroker,dc=local
2022-07-22 12:21:59 INFO  establishing new connection with retry_max=11
2022-07-22 12:21:59 INFO  bind binddn=cn=admin,dc=idbroker,dc=local
2022-07-22 12:22:00 INFO  Already attached!
2022-07-22 12:22:00 ERROR Failed to create school 'auth1-school1': Session is closed
Traceback (most recent call last):
  File "/kelvin/kelvin-api/ucsschool/kelvin/routers/school.py", line 341, in create
    await create_ou(**create_kwargs)
  File "/kelvin/ucs-school-lib/modules/ucsschool/lib/create_ou.py", line 165, in create_ou
    res = await new_school.create(lo)
  File "/kelvin/ucs-school-lib/modules/ucsschool/lib/models/base.py", line 608, in create
    success = await self.create_without_hooks(lo, validate)
  File "/kelvin/ucs-school-lib/modules/ucsschool/lib/models/school.py", line 559, in create_without_hooks
    await self.create_default_groups(lo)
  File "/kelvin/ucs-school-lib/modules/ucsschool/lib/models/school.py", line 255, in create_default_groups
    await udm_obj.save()
  File "/usr/lib/python3.8/site-packages/udm_rest_client/base_http.py", line 686, in save
    _, status, header = await self._udm_module.session.call_openapi(**kwargs)
  File "/usr/lib/python3.8/site-packages/udm_rest_client/base_http.py", line 404, in call_openapi
    api_model_obj, status, header = await meth(**kwargs)
  File "/usr/lib/python3.8/site-packages/openapi_client_udm/api_client.py", line 185, in __call_api
    response_data = await self.request(
  File "/usr/lib/python3.8/site-packages/openapi_client_udm/rest.py", line 240, in PATCH
    return (await self.request("PATCH", url,
  File "/usr/lib/python3.8/site-packages/openapi_client_udm/rest.py", line 166, in request
    r = await self.pool_manager.request(**args)
  File "/usr/lib/python3.8/site-packages/aiohttp/client.py", line 399, in _request
    raise RuntimeError("Session is closed")
RuntimeError: Session is closed

in the KELVIN API. So seems that somehow lost the connection to UDM REST.

I end up with the following object on the broker side for the school.

# auth1-school1, idbroker.local
dn: ou=auth1-school1,dc=idbroker,dc=local
ou: auth1-school1
displayName: school1
ucsschoolRole: school:school:auth1-school1
objectClass: organizationalUnit
objectClass: univentionObject
objectClass: top
objectClass: ucsschoolOrganizationalUnit
univentionObjectType: container/ou

And now we are kind of stuck because the ou is missing ucsschoolRecordUID and ucsschoolSourceUID. Any further attempt to sync objects from auth1-school1 fails, because provisioning cant find the school (missing ucsschoolRecordUID) but also can't create the school ou (as it already exists). 

I have seen this just in manual tests and only when deleting already synced school OU's on the broker side and doing a resync (or just creating an additional user on the school side). So this is probably not a "real world" problem but annoying for testing.