search

p2-inc / keycloak-events

Useful Keycloak event listener implementations and utilities.
https://phasetwo.io
Other
194 stars 37 forks source link

Incorrect webhook data response #42

Closed 2tvenom closed 1 year ago

2tvenom commented 1 year ago

Keycloak 22.0.5, plugin version 0.21

When try receive webhook information by id

curl -H 'Content-Type: application/json' -H "Authorization: Bearer $KEYCLOAK_AUTH" -X GET localhost:8081/realms/dummy/webhooks/9e2e0b52-a485-44ee-b623-6e19443fe3c2

i receive incorrect response. It contain two jsons, one with part of webhook information and second with unknown error at end

{"id":"9e2e0b52-a485-44ee-b623-6e19443fe3c2","enabled":true,"url":"https://pipedream.m.pipedream.net","createdBy":"13d9e184-8eda-48c5-b66c-6f4857f71834","createdAt":1699542940528,"realm":"dummy","eventTypes"}{"error":"unknown_error"}
xgp commented 1 year ago

Thanks for the report @2tvenom . I'm not able to reproduce, and the WebhooksResourceTest.testAddGetWebhook tests for this. Can you give me more information about your setup? I.e. how you created the webhook? Were there any exceptions in the Keycloak logs?

From where the error is occurring, it looks like there might be a problem with the converting the eventTypes from enum to JSON strings.

2tvenom commented 1 year ago

request

curl --verbose -H 'Content-Type: application/json' -H "Authorization: Bearer $KEYCLOAK_AUTH" -X POST localhost:8081/realms/dummy/webhooks -d '{
  "enabled": "true",
  "url": "https://pipedream.m.pipedream.net",
  "secret": "A3jt6D8lz",
  "eventTypes": [
    "access.REMOVE_TOTP",
    "access.UPDATE_TOTP",
    "access.LOGIN",
    "access.LOGOUT",
    "access.REGISTER",
    "access.UPDATE_PASSWORD",
    "access.VERIFY_EMAIL",
    "access.SEND_VERIFY_EMAIL",
    "access.RESET_PASSWORD"
  ]
}'
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 127.0.0.1:8081...
* Connected to localhost (127.0.0.1) port 8081 (#0)
> POST /realms/dummy/webhooks HTTP/1.1
> Host: localhost:8081
> User-Agent: curl/8.1.2
> Accept: */*
> Content-Type: application/json
> Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJPOGNyNzNLUjZpd3BvVTZzaE53d2FrXzVWQ2hlU3dGTzcwaW1Ic1V1VmtJIn0.eyJleHAiOjE2OTk1NDI5ODAsImlhdCI6MTY5OTU0MjkyMCwianRpIjoiZWU3MDdlYzYtMGUyNy00ZGNjLWE4NDItYjA1NjhjMzgwZjMxIiwiaXNzIjoiaHR0cDovL2xvY2FsaG9zdDo4MDgxL3JlYWxtcy9tYXN0ZXIiLCJzdWIiOiIxM2Q5ZTE4NC04ZWRhLTQ4YzUtYjY2Yy02ZjQ4NTdmNzE4MzQiLCJ0eXAiOiJCZWFyZXIiLCJhenAiOiJhZG1pbi1jbGkiLCJzZXNzaW9uX3N0YXRlIjoiZDQ2Mzk3MWUtOTdlMi00MTJhLTk4OTctOTc4M2Q3MjI2NzQ3IiwiYWNyIjoiMSIsInNjb3BlIjoicHJvZmlsZSBlbWFpbCIsInNpZCI6ImQ0NjM5NzFlLTk3ZTItNDEyYS05ODk3LTk3ODNkNzIyNjc0NyIsImVtYWlsX3ZlcmlmaWVkIjpmYWxzZSwicHJlZmVycmVkX3VzZXJuYW1lIjoiYWRtaW4ifQ.iHLIy6QywT4h9RbyM0J9OG16M2SAgOADI4FNfMT0HLcflTe6TWSOd2H_d5yekrk9stg59xIbBY1SID7YNRgtLfGtHgFcXQ_xCPXC8fdyYIN0SMDsre8URKuUCNlX2EfMkkrkqi3Aw_voO53A74VLyVGmbS0RVZPgrLW8xqqZj4SRUJcOUEO3-wf92-YhtzDTHM4N_p032nsXsMlR0SkLL71V8rp5PPXzWoD6EixDoEDwZsFBmA0IwpBPXLaGmkWkk1wBfWL-ZcMEm90_Rj-Y5HZ7L4MyGcdeZe7YlrBIYX4FHeDlcd9mKH4sXadWhQSqldbvqyGuUVl4aCC4uMBgFw
> Content-Length: 356
>
< HTTP/1.1 201 Created
< Referrer-Policy: no-referrer
< X-Frame-Options: SAMEORIGIN
< Strict-Transport-Security: max-age=31536000; includeSubDomains
< X-Content-Type-Options: nosniff
< X-XSS-Protection: 1; mode=block
< Location: http://localhost:8081/admin/realms/dummy/webhooks/9e2e0b52-a485-44ee-b623-6e19443fe3c2
< content-length: 0
<
* Connection #0 to host localhost left intact

no exceptions in logs

processing-keycloak-1  | 2023-11-09 15:53:54,631 ERROR [org.keycloak.services] (executor-thread-2030) KC-SERVICES0083: Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:54:03,497 ERROR [org.keycloak.services] (executor-thread-2030) KC-SERVICES0083: Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:54:07,799 ERROR [org.keycloak.services] (executor-thread-2030) KC-SERVICES0083: Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:54:09,307 ERROR [org.keycloak.services] (executor-thread-2030) KC-SERVICES0083: Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:54:10,325 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2031) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:54:10,327 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2030) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:54:10,327 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2032) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:55:00,861 ERROR [org.keycloak.services] (executor-thread-2032) KC-SERVICES0083: Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:55:05,425 ERROR [org.keycloak.services] (executor-thread-2032) KC-SERVICES0083: Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:55:05,434 ERROR [org.keycloak.services] (executor-thread-2032) KC-SERVICES0083: Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:55:10,329 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2032) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:55:10,329 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2032) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:55:10,331 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2032) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:56:10,328 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2032) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:56:10,328 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2033) Event listener 'metrics-listener' registered, but provider not found
processing-keycloak-1  | 2023-11-09 15:56:10,330 ERROR [org.keycloak.events.EventBuilder] (executor-thread-2033) Event listener 'metrics-listener' registered, but provider not found
xgp commented 1 year ago

Thanks for the additional info. Still not able to repro @2tvenom. See my bash script with all the steps I'm taking, and let me know if you are doing anything different:


#!/bin/bash

host=http://127.0.0.1:8082
realm=master
user=admin
pass=admin

# Get an access token
DIRECT_GRANT_RESPONSE=$(curl -i --request POST $host/auth/realms/$realm/protocol/openid-connect/token --header "Accept: application/json" --header "Content-Type: application/x-www-form-urlencoded" --data "grant_type=password&username=$user&password=$pass&client_id=admin-cli")
ACCESS_TOKEN=$(echo $DIRECT_GRANT_RESPONSE | grep "access_token" | sed 's/.*\"access_token\":\"\([^\"]*\)\".*/\1/g');

# Construct the json request
json='{ "enabled": "true", "url": "https://pipedream.m.pipedream.net", "secret": "A3jt6D8lz", "eventTypes": [ "access.REMOVE_TOTP", "access.UPDATE_TOTP", "access.LOGIN", "access.LOGOUT", "access.REGISTER", "access.UPDATE_PASSWORD", "access.VERIFY_EMAIL", "access.SEND_VERIFY_EMAIL", "access.RESET_PASSWORD" ] }'

# Create the webhook on the server, and get the id from the location header
response=$(curl --request POST $host/auth/realms/$realm/webhooks --header "Content-Type: application/json" --header "Accept: application/json" --header "Authorization: Bearer $ACCESS_TOKEN" -d "$json")
headers=$(sed -n '1,/^\r$/p' <<<"$response")
content=$(sed -e '1,/^\r$/d' -e '$d' <<<"$response")
read -r http_code size_header redirect_url < <(tail -n1 <<<"$response")
location=$(grep -oP 'Location: \K.*' <<<"$headers")
id=$(basename $location)

# Do a get on that webhook
curl -vv $host/auth/realms/$realm/webhooks/$id --header "Accept: application/json" --header "Authorization: Bearer $ACCESS_TOKEN"
2tvenom commented 1 year ago

prepare

# auth
KEYCLOAK_AUTH=$(curl -s -X POST --location "http://localhost:8081/realms/master/protocol/openid-connect/token" -H "Content-Type: application/x-www-form-urlencoded" -d "client_id=admin-cli&username=admin&password=admin&grant_type=password" | jq -r '.access_token')

#clear all webhooks
curl -H 'Content-Type: application/json' -H "Authorization: Bearer $KEYCLOAK_AUTH" -X GET localhost:8081/realms/master/webhooks  | jq -r '.[]|.id' | xargs -n 1 -I {} curl -H 'Content-Type: application/json' -H "Authorization: Bearer $KEYCLOAK_AUTH" -X DELETE localhost:8081/realms/master/webhooks/{}

run script. small changes, because macos

#!/bin/bash

host=http://127.0.0.1:8081
realm=master
user=admin
pass=admin

# Get an access token
DIRECT_GRANT_RESPONSE=$(curl -i --request POST $host/realms/$realm/protocol/openid-connect/token --header "Accept: application/json" --header "Content-Type: application/x-www-form-urlencoded" --data "grant_type=password&username=$user&password=$pass&client_id=admin-cli")
ACCESS_TOKEN=$(echo $DIRECT_GRANT_RESPONSE | grep "access_token" | sed 's/.*\"access_token\":\"\([^\"]*\)\".*/\1/g');

# Construct the json request
json='{ "enabled": "true", "url": "https://pipedream.m.pipedream.net", "secret": "A3jt6D8lz", "eventTypes": [ "access.REMOVE_TOTP", "access.UPDATE_TOTP", "access.LOGIN", "access.LOGOUT", "access.REGISTER", "access.UPDATE_PASSWORD", "access.VERIFY_EMAIL", "access.SEND_VERIFY_EMAIL", "access.RESET_PASSWORD" ] }'

# Create the webhook on the server, and get the id from the location header
response=$(curl --verbose --request POST $host/realms/$realm/webhooks --header "Content-Type: application/json" --header "Accept: application/json" --header "Authorization: Bearer $ACCESS_TOKEN" -d "$json" 2>&1)

echo "$response"

location=$(echo "$response" | awk -v FS=": " '/Location/{print $2}' | tr -d '\r')
id=$(basename $location)

# Do a get on that webhook
curl -v --header "Accept: application/json" --header "Authorization: Bearer $ACCESS_TOKEN" $host/realms/$realm/webhooks/$id

final log

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1887  100  1818  100    69  39251   1489 --:--:-- --:--:-- --:--:-- 43883
Note: Unnecessary use of -X or --request, POST is already inferred.
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 127.0.0.1:8081...
* Connected to 127.0.0.1 (127.0.0.1) port 8081 (#0)
> POST /realms/master/webhooks HTTP/1.1
> Host: 127.0.0.1:8081
> User-Agent: curl/8.1.2
> Content-Type: application/json
> Accept: application/json
> Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJPOGNyNzNLUjZpd3BvVTZzaE53d2FrXzVWQ2hlU3dGTzcwaW1Ic1V1VmtJIn0.eyJleHAiOjE2OTk1Njg0OTUsImlhdCI6MTY5OTU2ODQzNSwianRpIjoiMWJiODdiNWQtZjc5Zi00YTczLTliN2UtZjc5Njg5Nzg3NDVhIiwiaXNzIjoiaHR0cDovLzEyNy4wLjAuMTo4MDgxL3JlYWxtcy9tYXN0ZXIiLCJzdWIiOiIxM2Q5ZTE4NC04ZWRhLTQ4YzUtYjY2Yy02ZjQ4NTdmNzE4MzQiLCJ0eXAiOiJCZWFyZXIiLCJhenAiOiJhZG1pbi1jbGkiLCJzZXNzaW9uX3N0YXRlIjoiNTNlZTk0YmYtMmYzNi00MDM3LWE0MjctMzI3M2JkYWU5NjRiIiwiYWNyIjoiMSIsInNjb3BlIjoicHJvZmlsZSBlbWFpbCIsInNpZCI6IjUzZWU5NGJmLTJmMzYtNDAzNy1hNDI3LTMyNzNiZGFlOTY0YiIsImVtYWlsX3ZlcmlmaWVkIjpmYWxzZSwicHJlZmVycmVkX3VzZXJuYW1lIjoiYWRtaW4ifQ.d6N8wbWtg_7M70USYAbfqojsXsbQzCZtHH9IocAmvwHlr7Vjo7OvXAzGk-zQs65bfFyH-De_yt_3O9dDqF8_ffNvt03w-O38u2VyovMqWY98iNvDo6iMP5uhcJvEEVx6zc6b0xqY6gJ0A4h55St2HYhj1FyzOCX7IfZjv652AbGIZ55j8jIFdvYs6jbAsdLOa50ikrivY4hq2N5g-kWMmPust0n52hDjb-_CGEs5PKxqwvYmqgWUCCMf2TkZWWlVeARutNZTBI7okCFerRIijOk_t8PvAb7oeD5xPDdV7nXD0ogyvXYoPwbVtvfo4sF_SoGjYuwxzKPYYpmt7Xiovg
> Content-Length: 304
> 
} [304 bytes data]
< HTTP/1.1 201 Created
< Referrer-Policy: no-referrer
< X-Frame-Options: SAMEORIGIN
< Strict-Transport-Security: max-age=31536000; includeSubDomains
< X-Content-Type-Options: nosniff
< X-XSS-Protection: 1; mode=block
< Location: http://127.0.0.1:8081/admin/realms/master/webhooks/ad5a954f-b4bc-46fc-95cf-de3b00b44bee
< content-length: 0
< 
100   304    0     0  100   304      0  30703 --:--:-- --:--:-- --:--:-- 43428
* Connection #0 to host 127.0.0.1 left intact
*   Trying 127.0.0.1:8081...
* Connected to 127.0.0.1 (127.0.0.1) port 8081 (#0)
> GET /realms/master/webhooks/ad5a954f-b4bc-46fc-95cf-de3b00b44bee HTTP/1.1
> Host: 127.0.0.1:8081
> User-Agent: curl/8.1.2
> Accept: application/json
> Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJPOGNyNzNLUjZpd3BvVTZzaE53d2FrXzVWQ2hlU3dGTzcwaW1Ic1V1VmtJIn0.eyJleHAiOjE2OTk1Njg0OTUsImlhdCI6MTY5OTU2ODQzNSwianRpIjoiMWJiODdiNWQtZjc5Zi00YTczLTliN2UtZjc5Njg5Nzg3NDVhIiwiaXNzIjoiaHR0cDovLzEyNy4wLjAuMTo4MDgxL3JlYWxtcy9tYXN0ZXIiLCJzdWIiOiIxM2Q5ZTE4NC04ZWRhLTQ4YzUtYjY2Yy02ZjQ4NTdmNzE4MzQiLCJ0eXAiOiJCZWFyZXIiLCJhenAiOiJhZG1pbi1jbGkiLCJzZXNzaW9uX3N0YXRlIjoiNTNlZTk0YmYtMmYzNi00MDM3LWE0MjctMzI3M2JkYWU5NjRiIiwiYWNyIjoiMSIsInNjb3BlIjoicHJvZmlsZSBlbWFpbCIsInNpZCI6IjUzZWU5NGJmLTJmMzYtNDAzNy1hNDI3LTMyNzNiZGFlOTY0YiIsImVtYWlsX3ZlcmlmaWVkIjpmYWxzZSwicHJlZmVycmVkX3VzZXJuYW1lIjoiYWRtaW4ifQ.d6N8wbWtg_7M70USYAbfqojsXsbQzCZtHH9IocAmvwHlr7Vjo7OvXAzGk-zQs65bfFyH-De_yt_3O9dDqF8_ffNvt03w-O38u2VyovMqWY98iNvDo6iMP5uhcJvEEVx6zc6b0xqY6gJ0A4h55St2HYhj1FyzOCX7IfZjv652AbGIZ55j8jIFdvYs6jbAsdLOa50ikrivY4hq2N5g-kWMmPust0n52hDjb-_CGEs5PKxqwvYmqgWUCCMf2TkZWWlVeARutNZTBI7okCFerRIijOk_t8PvAb7oeD5xPDdV7nXD0ogyvXYoPwbVtvfo4sF_SoGjYuwxzKPYYpmt7Xiovg
> 
< HTTP/1.1 400 Bad Request
< Referrer-Policy: no-referrer
< X-Frame-Options: SAMEORIGIN
< Strict-Transport-Security: max-age=31536000; includeSubDomains
< X-Content-Type-Options: nosniff
< X-XSS-Protection: 1; mode=block
< Content-Type: application/json
< content-length: 234
< 
* Connection #0 to host 127.0.0.1 left intact
{"id":"ad5a954f-b4bc-46fc-95cf-de3b00b44bee","enabled":true,"url":"https://pipedream.m.pipedream.net","createdBy":"13d9e184-8eda-48c5-b66c-6f4857f71834","createdAt":1699568435450,"realm":"master","eventTypes"}{"error":"unknown_error"}
xgp commented 1 year ago

Weird. I still don’t see the error. Are you running a Keycloak from scratch? Any other initial state? Can you turn on DEBUG logging and see if you see any exceptions?

2tvenom commented 1 year ago

yes, got it

processing-keycloak-1  | 2023-11-10 15:42:45,244 DEBUG [org.hibernate.internal.util.EntityPrinter] (executor-thread-1) Listing entities:
processing-keycloak-1  | 2023-11-10 15:42:45,244 DEBUG [org.hibernate.internal.util.EntityPrinter] (executor-thread-1) io.phasetwo.keycloak.model.jpa.entity.WebhookEntity{createdAt=Fri Nov 10 15:42:45 GMT 2023, realmId=b95e22c3-0c24-4edf-b27e-c5b4aae4fc97, createdBy=9f2efea1-1d04-4dad-aa04-d654388f9bb1, id=df954de3-83b6-4920-a601-37b3685edeca, secret=null, eventTypes=[], enabled=false, url=https://pipedream.m.pipedream.net, algorithm=null}
processing-keycloak-1  | 2023-11-10 15:42:45,244 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK (ALGORITHM,CREATED_AT,CREATED_BY_USER_ID,ENABLED,REALM_ID,SECRET,URL,ID) values (?,?,?,?,?,?,?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,245 DEBUG [org.hibernate.orm.jdbc.mutation] (executor-thread-1) Inserting collection rows - io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes : df954de3-83b6-4920-a601-37b3685edeca
processing-keycloak-1  | 2023-11-10 15:42:45,245 DEBUG [org.hibernate.orm.jdbc.mutation] (executor-thread-1) No collection rows to insert - io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes : df954de3-83b6-4920-a601-37b3685edeca
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) JtaTransactionWrapper  commit
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Processing flush-time cascades
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Dirty checking collections
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.engine.spi.CollectionEntry] (executor-thread-1) Collection dirty: [io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes#df954de3-83b6-4920-a601-37b3685edeca]
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.engine.internal.Collections] (executor-thread-1) Collection found: [io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes#df954de3-83b6-4920-a601-37b3685edeca], was: [io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes#df954de3-83b6-4920-a601-37b3685edeca] (initialized)
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Flushed: 0 (re)creations, 1 updates, 0 removals to 1 collections
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.internal.util.EntityPrinter] (executor-thread-1) Listing entities:
processing-keycloak-1  | 2023-11-10 15:42:45,246 DEBUG [org.hibernate.internal.util.EntityPrinter] (executor-thread-1) io.phasetwo.keycloak.model.jpa.entity.WebhookEntity{createdAt=Fri Nov 10 15:42:45 GMT 2023, realmId=b95e22c3-0c24-4edf-b27e-c5b4aae4fc97, createdBy=9f2efea1-1d04-4dad-aa04-d654388f9bb1, id=df954de3-83b6-4920-a601-37b3685edeca, secret=A3jt6D8lz, eventTypes=[access.RESET_PASSWORD, access.UPDATE_TOTP, access.LOGIN, access.LOGOUT, access.SEND_VERIFY_EMAIL, access.REMOVE_TOTP, access.VERIFY_EMAIL, access.UPDATE_PASSWORD, access.REGISTER], enabled=true, url=https://pipedream.m.pipedream.net, algorithm=HmacSHA256}
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.SQL] (executor-thread-1) update WEBHOOK set ALGORITHM=?,CREATED_AT=?,CREATED_BY_USER_ID=?,ENABLED=?,REALM_ID=?,SECRET=?,URL=? where ID=?
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.orm.jdbc.mutation] (executor-thread-1) Deleting removed collection rows - io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes : df954de3-83b6-4920-a601-37b3685edeca
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.orm.jdbc.mutation] (executor-thread-1) No rows to delete
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.orm.jdbc.mutation] (executor-thread-1) Inserting collection rows - io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes : df954de3-83b6-4920-a601-37b3685edeca
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,247 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.SQL] (executor-thread-1) insert into WEBHOOK_EVENT_TYPES (WEBHOOK_ID,VALUE) values (?,?)
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.orm.jdbc.mutation] (executor-thread-1) Done inserting `9` collection rows : io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (executor-thread-1) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (executor-thread-1) Initiating JDBC connection release from beforeTransactionCompletion
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (executor-thread-1) Initiating JDBC connection release from afterTransaction
processing-keycloak-1  | 2023-11-10 15:42:45,248 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) JtaTransactionWrapper end
processing-keycloak-1  | 2023-11-10 15:42:45,265 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) new JtaTransactionWrapper
processing-keycloak-1  | 2023-11-10 15:42:45,265 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) was existing? false
processing-keycloak-1  | 2023-11-10 15:42:45,266 DEBUG [io.phasetwo.keycloak.resources.BaseRealmResourceProvider] (executor-thread-1) request method GET
processing-keycloak-1  | 2023-11-10 15:42:45,266 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (executor-thread-1) `hibernate.connection.provider_disables_autocommit` was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
processing-keycloak-1  | 2023-11-10 15:42:45,266 DEBUG [org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] (executor-thread-1) Hibernate RegisteredSynchronization successfully registered with JTA platform
processing-keycloak-1  | 2023-11-10 15:42:45,268 DEBUG [org.keycloak.services.resources.Cors] (executor-thread-1) Added CORS headers to response
processing-keycloak-1  | 2023-11-10 15:42:45,268 DEBUG [org.hibernate.orm.sql.exec] (executor-thread-1) Skipping reading Query result cache data: cache-enabled = false, cache-mode = IGNORE
processing-keycloak-1  | 2023-11-10 15:42:45,268 DEBUG [org.hibernate.orm.results] (executor-thread-1) Initializer list
processing-keycloak-1  | 2023-11-10 15:42:45,268 DEBUG [org.hibernate.orm.results] (executor-thread-1)     io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes -> DelayedCollectionInitializer(io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes)@2107967438 (PluralAttribute(io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes))
processing-keycloak-1  | 2023-11-10 15:42:45,268 DEBUG [org.hibernate.orm.results] (executor-thread-1)     io.phasetwo.keycloak.model.jpa.entity.WebhookEntity -> EntityResultInitializer(io.phasetwo.keycloak.model.jpa.entity.WebhookEntity)@983918022 (SingleTableEntityPersister(io.phasetwo.keycloak.model.jpa.entity.WebhookEntity))
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.SQL] (executor-thread-1) select w1_0.ID,w1_0.ALGORITHM,w1_0.CREATED_AT,w1_0.CREATED_BY_USER_ID,w1_0.ENABLED,w1_0.REALM_ID,w1_0.SECRET,w1_0.URL from WEBHOOK w1_0 where w1_0.ID=?
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results.loading.entity] (executor-thread-1) (EntityResultInitializer) Hydrated EntityKey (io.phasetwo.keycloak.model.jpa.entity.WebhookEntity): df954de3-83b6-4920-a601-37b3685edeca
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [0] - [df954de3-83b6-4920-a601-37b3685edeca]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results.loading.org.hibernate.orm.results.loading.collection] (executor-thread-1) (DelayedCollectionInitializer) Current row collection key : io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes#df954de3-83b6-4920-a601-37b3685edeca
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results.loading.entity] (executor-thread-1) (EntityResultInitializer) Created new entity instance [io.phasetwo.keycloak.model.jpa.entity.WebhookEntity#df954de3-83b6-4920-a601-37b3685edeca] : 480201284
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [1] - [HmacSHA256]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [2] - [2023-11-10 15:42:45.243]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [3] - [9f2efea1-1d04-4dad-aa04-d654388f9bb1]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [4] - [true]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [5] - [b95e22c3-0c24-4edf-b27e-c5b4aae4fc97]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [6] - [A3jt6D8lz]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results] (executor-thread-1) Extracted JDBC value [7] - [https://pipedream.m.pipedream.net]
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results.loading.entity] (executor-thread-1) (EntityResultInitializer) Done materializing entityInstance : io.phasetwo.keycloak.model.jpa.entity.WebhookEntity#df954de3-83b6-4920-a601-37b3685edeca
processing-keycloak-1  | 2023-11-10 15:42:45,269 DEBUG [org.hibernate.orm.results.loading] (executor-thread-1) Calling top-level assembler (0 / 1) : org.hibernate.sql.results.graph.entity.internal.EntityAssembler@683cd849
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) JtaTransactionWrapper  commit
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Processing flush-time cascades
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Dirty checking collections
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.hibernate.engine.internal.Collections] (executor-thread-1) Skipping uninitialized bytecode-lazy collection: [io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes#df954de3-83b6-4920-a601-37b3685edeca]
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (executor-thread-1) Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.hibernate.internal.util.EntityPrinter] (executor-thread-1) Listing entities:
processing-keycloak-1  | 2023-11-10 15:42:45,270 DEBUG [org.hibernate.internal.util.EntityPrinter] (executor-thread-1) io.phasetwo.keycloak.model.jpa.entity.WebhookEntity{createdAt=2023-11-10 15:42:45.243, realmId=b95e22c3-0c24-4edf-b27e-c5b4aae4fc97, createdBy=9f2efea1-1d04-4dad-aa04-d654388f9bb1, id=df954de3-83b6-4920-a601-37b3685edeca, secret=A3jt6D8lz, eventTypes=<uninitialized>, enabled=true, url=https://pipedream.m.pipedream.net, algorithm=HmacSHA256}
processing-keycloak-1  | 2023-11-10 15:42:45,271 DEBUG [org.hibernate.engine.transaction.internal.TransactionImpl] (executor-thread-1) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
processing-keycloak-1  | 2023-11-10 15:42:45,271 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (executor-thread-1) Initiating JDBC connection release from beforeTransactionCompletion
processing-keycloak-1  | 2023-11-10 15:42:45,271 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (executor-thread-1) Initiating JDBC connection release from afterTransaction
processing-keycloak-1  | 2023-11-10 15:42:45,271 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) JtaTransactionWrapper end
processing-keycloak-1  | 2023-11-10 15:42:45,278 DEBUG [org.keycloak.services.error.KeycloakErrorHandler] (executor-thread-1) Error response 400: com.fasterxml.jackson.databind.JsonMappingException: failed to lazily initialize a collection of role: io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes: could not initialize proxy - no Session (through reference chain: io.phasetwo.keycloak.representation.WebhookRepresentation["eventTypes"])
processing-keycloak-1  |    at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:402)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:361)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.std.StdSerializer.wrapAndThrow(StdSerializer.java:323)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:780)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:178)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:479)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:318)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.java:1572)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:1061)
processing-keycloak-1  |    at org.jboss.resteasy.plugins.providers.jackson.ResteasyJackson2Provider.writeTo(ResteasyJackson2Provider.java:332)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext.lambda$writeTo$1(ServerWriterInterceptorContext.java:74)
processing-keycloak-1  |    at io.quarkus.resteasy.runtime.standalone.VertxHttpRequest$VertxExecutionContext.executeBlockingIo(VertxHttpRequest.java:251)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext.writeTo(ServerWriterInterceptorContext.java:73)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.AbstractWriterInterceptorContext.syncProceed(AbstractWriterInterceptorContext.java:224)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.AbstractWriterInterceptorContext.proceed(AbstractWriterInterceptorContext.java:207)
processing-keycloak-1  |    at org.keycloak.quarkus.runtime.integration.jaxrs.TransactionalResponseInterceptor.aroundWriteTo(TransactionalResponseInterceptor.java:42)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.AbstractWriterInterceptorContext.syncProceed(AbstractWriterInterceptorContext.java:231)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.AbstractWriterInterceptorContext.getStarted(AbstractWriterInterceptorContext.java:161)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext.lambda$getStarted$0(ServerWriterInterceptorContext.java:68)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext.aroundWriteTo(ServerWriterInterceptorContext.java:87)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.ServerWriterInterceptorContext.getStarted(ServerWriterInterceptorContext.java:68)
processing-keycloak-1  |    at org.jboss.resteasy.core.ServerResponseWriter.lambda$writeNomapResponse$3(ServerResponseWriter.java:166)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.ContainerResponseContextImpl.filter(ContainerResponseContextImpl.java:365)
processing-keycloak-1  |    at org.jboss.resteasy.core.ServerResponseWriter.executeFilters(ServerResponseWriter.java:243)
processing-keycloak-1  |    at org.jboss.resteasy.core.ServerResponseWriter.writeNomapResponse(ServerResponseWriter.java:100)
processing-keycloak-1  |    at org.jboss.resteasy.core.ServerResponseWriter.writeNomapResponse(ServerResponseWriter.java:73)
processing-keycloak-1  |    at org.jboss.resteasy.core.SynchronousDispatcher.writeResponse(SynchronousDispatcher.java:518)
processing-keycloak-1  |    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:458)
processing-keycloak-1  |    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:240)
processing-keycloak-1  |    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
processing-keycloak-1  |    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
processing-keycloak-1  |    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
processing-keycloak-1  |    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:229)
processing-keycloak-1  |    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:82)
processing-keycloak-1  |    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:147)
processing-keycloak-1  |    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:84)
processing-keycloak-1  |    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.handle(VertxRequestHandler.java:44)
processing-keycloak-1  |    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
processing-keycloak-1  |    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
processing-keycloak-1  |    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
processing-keycloak-1  |    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:58)
processing-keycloak-1  |    at io.quarkus.vertx.http.runtime.options.HttpServerCommonHandlers$1.handle(HttpServerCommonHandlers.java:36)
processing-keycloak-1  |    at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1284)
processing-keycloak-1  |    at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:177)
processing-keycloak-1  |    at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)
processing-keycloak-1  |    at org.keycloak.quarkus.runtime.integration.web.QuarkusRequestFilter.lambda$createBlockingHandler$0(QuarkusRequestFilter.java:82)
processing-keycloak-1  |    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
processing-keycloak-1  |    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
processing-keycloak-1  |    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
processing-keycloak-1  |    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
processing-keycloak-1  |    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
processing-keycloak-1  |    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
processing-keycloak-1  |    at java.base/java.lang.Thread.run(Thread.java:840)
processing-keycloak-1  | Caused by: org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: io.phasetwo.keycloak.model.jpa.entity.WebhookEntity.eventTypes: could not initialize proxy - no Session
processing-keycloak-1  |    at org.hibernate.collection.spi.AbstractPersistentCollection.throwLazyInitializationException(AbstractPersistentCollection.java:635)
processing-keycloak-1  |    at org.hibernate.collection.spi.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:218)
processing-keycloak-1  |    at org.hibernate.collection.spi.AbstractPersistentCollection.readSize(AbstractPersistentCollection.java:148)
processing-keycloak-1  |    at org.hibernate.collection.spi.PersistentSet.size(PersistentSet.java:151)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.impl.StringCollectionSerializer.serialize(StringCollectionSerializer.java:70)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.impl.StringCollectionSerializer.serialize(StringCollectionSerializer.java:22)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:732)
processing-keycloak-1  |    at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:772)
processing-keycloak-1  |    ... 49 more
processing-keycloak-1  |
processing-keycloak-1  | 2023-11-10 15:42:46,647 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) new JtaTransactionWrapper
processing-keycloak-1  | 2023-11-10 15:42:46,647 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) was existing? false
processing-keycloak-1  | 2023-11-10 15:42:46,649 DEBUG [org.keycloak.services.scheduled.ScheduledTaskRunner] (Timer-0) Executed scheduled task AbstractLastSessionRefreshStoreFactory$$Lambda$1858/0x0000000100e2ac00
processing-keycloak-1  | 2023-11-10 15:42:46,649 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper  commit
processing-keycloak-1  | 2023-11-10 15:42:46,649 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (Timer-0) JtaTransactionWrapper end
processing-keycloak-1  | 2023-11-10 15:42:47,716 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) new JtaTransactionWrapper
processing-keycloak-1  | 2023-11-10 15:42:47,716 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-1) was existing? false
processing-keycloak-1  | 2023-11-10 15:42:47,715 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-2) new JtaTransactionWrapper
processing-keycloak-1  | 2023-11-10 15:42:47,716 DEBUG [org.keycloak.transaction.JtaTransactionWrapper] (executor-thread-2) was existing? false
processing-keycloak-1  | 2023-11-10 15:42:47,717 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (executor-thread-1) `hibernate.connection.provider_disables_autocommit` was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
processing-keycloak-1  | 2023-11-10 15:42:47,717 DEBUG [org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] (executor-thread-1) Hibernate RegisteredSynchronization successfully registered with JTA platform
processing-keycloak-1  | 2023-11-10 15:42:47,717 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (executor-thread-2) `hibernate.connection.provider_disables_autocommit` was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
processing-keycloak-1  | 2023-11-10 15:42:47,718 DEBUG [org.hibernate.orm.sql.exec] (executor-thread-1) Skipping reading Query result cache data: cache-enabled = false, cache-mode = NORMAL
2tvenom commented 1 year ago

for clarify. i'am testing this extension in docker with start-dev

docker image quay.io/keycloak/keycloak:22.0.5 and added extendions:

xgp commented 1 year ago

Thanks again for all of the detail @2tvenom . I'll recreate your environment and tests next week to see if I can reproduce the bug.

xgp commented 1 year ago

It looks like there are some situations where the JPA/Hibernate session is closed when serializing the event types to JSON. I haven't been able to figure out where it happens, but I switched the eventTypes collection to FetchType.EAGER, and that seems to stop it. @2tvenom Please try building from the branch xgp/bug-42 and let me know if that works in your situation.

2tvenom commented 1 year ago

i checked it. working correctly

./webhook_test.sh
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1887  100  1818  100    69   5194    197 --:--:-- --:--:-- --:--:--  5453
Note: Unnecessary use of -X or --request, POST is already inferred.
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 127.0.0.1:8081...
* Connected to 127.0.0.1 (127.0.0.1) port 8081 (#0)
> POST /realms/master/webhooks HTTP/1.1
> Host: 127.0.0.1:8081
> User-Agent: curl/8.1.2
> Content-Type: application/json
> Accept: application/json
> Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJpWkdkNFEtY2lyekNoeFNoeFFsVGkzbXo5cEJxcEhyN0FfZVhPcWFqT0NrIn0.eyJleHAiOjE2OTk5MDU4MDYsImlhdCI6MTY5OTkwNTc0NiwianRpIjoiNzcwNTBjZDMtYWM4Ni00NTg1LThmZTMtMzJiZGY4MDRmYTQ1IiwiaXNzIjoiaHR0cDovLzEyNy4wLjAuMTo4MDgxL3JlYWxtcy9tYXN0ZXIiLCJzdWIiOiI4NzdhODMxMy02MjA1LTQwMWQtYTI1YS1jN2U5MWNkMDAyYWUiLCJ0eXAiOiJCZWFyZXIiLCJhenAiOiJhZG1pbi1jbGkiLCJzZXNzaW9uX3N0YXRlIjoiZmQ2ODZkZTQtYjU2NC00MmExLTlkOGQtNjAzMzYwMjJlYjRkIiwiYWNyIjoiMSIsInNjb3BlIjoicHJvZmlsZSBlbWFpbCIsInNpZCI6ImZkNjg2ZGU0LWI1NjQtNDJhMS05ZDhkLTYwMzM2MDIyZWI0ZCIsImVtYWlsX3ZlcmlmaWVkIjpmYWxzZSwicHJlZmVycmVkX3VzZXJuYW1lIjoiYWRtaW4ifQ.clrn5YkCsdEtvCSiSLypRvsZ3EKsxJdocSWaN_Z1vkZkHZlcERGOWWsfjvf2llsM4aDsoXaElmMoRRA9dnmo5vKGnMZF1MLiv-HFM42eAjpW9i3UjMVnv3qVXDbz2oGKlxckXLZWSJGq_BB4WAZPnDWHMfREn8-T4Ha_DUTiBdGOmfoPSokJ8jDXki_hzfgLNNaECVp0hzRcZ-X8CMccpOXcxdNI1GVO0uay9qDqvbneDqCDpOmXXhRxueBhekaVgJCWbD1EfiVvKrC3q8xY6ZcugTcrpk9CplrmZZnseTdAaRAJDQ_LGxKEFhmyM2HEIMe7yZIY3wgI6dJ42C0iqg
> Content-Length: 304
>
} [304 bytes data]
< HTTP/1.1 201 Created
< Referrer-Policy: no-referrer
< X-Frame-Options: SAMEORIGIN
< Strict-Transport-Security: max-age=31536000; includeSubDomains
< X-Content-Type-Options: nosniff
< X-XSS-Protection: 1; mode=block
< Location: http://127.0.0.1:8081/admin/realms/master/webhooks/2509fa00-8e38-43a8-a0f4-9648b5f4b3f1
< content-length: 0
<
100   304    0     0  100   304      0   8997 --:--:-- --:--:-- --:--:--  9806
* Connection #0 to host 127.0.0.1 left intact
*   Trying 127.0.0.1:8081...
* Connected to 127.0.0.1 (127.0.0.1) port 8081 (#0)
> GET /realms/master/webhooks/2509fa00-8e38-43a8-a0f4-9648b5f4b3f1 HTTP/1.1
> Host: 127.0.0.1:8081
> User-Agent: curl/8.1.2
> Accept: application/json
> Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJpWkdkNFEtY2lyekNoeFNoeFFsVGkzbXo5cEJxcEhyN0FfZVhPcWFqT0NrIn0.eyJleHAiOjE2OTk5MDU4MDYsImlhdCI6MTY5OTkwNTc0NiwianRpIjoiNzcwNTBjZDMtYWM4Ni00NTg1LThmZTMtMzJiZGY4MDRmYTQ1IiwiaXNzIjoiaHR0cDovLzEyNy4wLjAuMTo4MDgxL3JlYWxtcy9tYXN0ZXIiLCJzdWIiOiI4NzdhODMxMy02MjA1LTQwMWQtYTI1YS1jN2U5MWNkMDAyYWUiLCJ0eXAiOiJCZWFyZXIiLCJhenAiOiJhZG1pbi1jbGkiLCJzZXNzaW9uX3N0YXRlIjoiZmQ2ODZkZTQtYjU2NC00MmExLTlkOGQtNjAzMzYwMjJlYjRkIiwiYWNyIjoiMSIsInNjb3BlIjoicHJvZmlsZSBlbWFpbCIsInNpZCI6ImZkNjg2ZGU0LWI1NjQtNDJhMS05ZDhkLTYwMzM2MDIyZWI0ZCIsImVtYWlsX3ZlcmlmaWVkIjpmYWxzZSwicHJlZmVycmVkX3VzZXJuYW1lIjoiYWRtaW4ifQ.clrn5YkCsdEtvCSiSLypRvsZ3EKsxJdocSWaN_Z1vkZkHZlcERGOWWsfjvf2llsM4aDsoXaElmMoRRA9dnmo5vKGnMZF1MLiv-HFM42eAjpW9i3UjMVnv3qVXDbz2oGKlxckXLZWSJGq_BB4WAZPnDWHMfREn8-T4Ha_DUTiBdGOmfoPSokJ8jDXki_hzfgLNNaECVp0hzRcZ-X8CMccpOXcxdNI1GVO0uay9qDqvbneDqCDpOmXXhRxueBhekaVgJCWbD1EfiVvKrC3q8xY6ZcugTcrpk9CplrmZZnseTdAaRAJDQ_LGxKEFhmyM2HEIMe7yZIY3wgI6dJ42C0iqg
>
< HTTP/1.1 200 OK
< Referrer-Policy: no-referrer
< X-Frame-Options: SAMEORIGIN
< Strict-Transport-Security: max-age=31536000; includeSubDomains
< X-Content-Type-Options: nosniff
< X-XSS-Protection: 1; mode=block
< Content-Type: application/json
< content-length: 400
<
* Connection #0 to host 127.0.0.1 left intact
{"id":"2509fa00-8e38-43a8-a0f4-9648b5f4b3f1","enabled":true,"url":"https://pipedream.m.pipedream.net","createdBy":"877a8313-6205-401d-a25a-c7e91cd002ae","createdAt":1699905746609,"realm":"master","eventTypes":["access.RESET_PASSWORD","access.UPDATE_TOTP","access.LOGIN","access.LOGOUT","access.SEND_VERIFY_EMAIL","access.REMOVE_TOTP","access.VERIFY_EMAIL","access.UPDATE_PASSWORD","access.REGISTER"]}