search

ory / kratos

The most scalable and customizable identity server on the market. Replace your Homegrown, Auth0, Okta, Firebase with better UX and DX. Has all the tablestakes: Passkeys, Social Sign In, Multi-Factor Auth, SMS, SAML, TOTP, and more. Written in Go, cloud native, headless, API-first. Available as a service on Ory Network and for self-hosters.
https://www.ory.sh/?utm_source=github&utm_medium=banner&utm_campaign=kratos
Apache License 2.0
11.13k stars 954 forks source link

Email Verification Error when using PostgreSQL #269

Closed flusflas closed 4 years ago

flusflas commented 4 years ago

Describe the bug

I am using PostgreSQL with Kratos. All worked fine, but now I am trying to add email verification and Kratos fails when registering a new user: the the user is created, but Kratos returns a 500 error ("pq: value too long for type character varying(255)").

I have tested the same scenario using SQLite and everything seems to work as expected. Is PostgreSQL fully supported or am I going too fast?

Reproducing the bug

This bug can be reproduced starting from the Quickstart sample project.

Steps to reproduce the behavior:

  1. Modify user schema (kratos/contrib/quickstart/kratos/email-password/identity.traits.schema.json) to:
{
  "$id": "https://schemas.ory.sh/presets/kratos/quickstart/email-password/identity.schema.json",
  "$schema": "http://json-schema.org/draft-07/schema#",
  "title": "Person",
  "type": "object",
  "properties": {
    "username": {
      "type": "string",
      "title": "Username",
      "minLength": 6,
      "ory.sh/kratos": {
        "credentials": {
          "password": {
            "identifier": true
          }
        }
      }
    },
    "email": {
      "type": "string",
      "format": "email",
      "title": "E-Mail",
      "minLength": 6,
      "ory.sh/kratos": {
        "verification": {
          "via": "email"
        }
      }
    }
  },
  "required": [
    "username",
    "email"
  ],
  "additionalProperties": false
}

Note that we are adding the email verification feature.

  1. Run docker-compose -f quickstart.yml up

  2. In this scenario, Kratos is using the default SQLite database. If we navigate to http://127.0.0.1:4455/auth/registration and try to register an user, everything should work (including sending verification email).

  3. Stop docker-compose. Run docker-compose -f quickstart.yml down -v

  4. Add a PostgreSQL database to quickstart.yml:

    postgresd:
image: postgres:latest
ports:
    - "5432:5432"
environment:
    - POSTGRES_DB=kratos
    - POSTGRES_USER=kratos
    - POSTGRES_PASSWORD=secret
networks:
    - intranet

  5. Change DSN in kratos-migrate and kratos containers to point to PostgreSQL:

    environment:
 - DSN=postgres://kratos:secret@postgresd:5432/kratos?sslmode=disable

  6. (Optional) Change kratos-migrate and kratos containers images to latest (although latest-sqlite works exactly equal).

At this point, quickstart.yml should look like this:

version: '3.7'

services:

  kratos-migrate:
    image: oryd/kratos:latest
    environment:
      - DSN=postgres://kratos:secret@postgresd:5432/kratos?sslmode=disable
    volumes:
      -
        type: volume
        source: kratos-sqlite
        target: /home/ory/sqlite
        read_only: false
      -
        type: bind
        source: ./contrib/quickstart/kratos/email-password
        target: /etc/config/kratos
    command:
      -c /etc/config/kratos/.kratos.yml migrate sql -e --yes
    restart: on-failure
    networks:
      - intranet

  kratos-selfservice-ui-node:
    image: oryd/kratos-selfservice-ui-node:latest
    ports:
      - "4435:4435"
    environment:
      - PORT=4435
      - KRATOS_PUBLIC_URL=http://kratos:4433/
      - KRATOS_ADMIN_URL=http://kratos:4434/
      - KRATOS_BROWSER_URL=http://127.0.0.1:4455/.ory/kratos/public
      - JWKS_URL=http://oathkeeper:4456/.well-known/jwks.json
    networks:
      - intranet
    restart: on-failure

  oathkeeper:
    image: oryd/oathkeeper:v0.35.5-beta.1
    depends_on:
      - kratos
    ports:
      - "4455:4455"
      - "4456:4456"
    command:
      serve proxy -c "/etc/config/oathkeeper/.oathkeeper.yml"
    environment:
      - LOG_LEVEL=debug
    restart: on-failure
    networks:
      - intranet
    volumes:
      -
        type: bind
        source: ./contrib/quickstart/oathkeeper
        target: /etc/config/oathkeeper

  kratos:
    depends_on:
      - kratos-migrate
    image: oryd/kratos:latest
    ports:
      - "4433:4433" # public
      - "4434:4434" # admin
    restart: unless-stopped
    environment:
      - DSN=postgres://kratos:secret@postgresd:5432/kratos?sslmode=disable
    command:
      serve -c /etc/config/kratos/.kratos.yml --dev
    volumes:
      -
        type: volume
        source: kratos-sqlite
        target: /home/ory/sqlite
        read_only: false
      -
        type: bind
        source: ./contrib/quickstart/kratos/email-password
        target: /etc/config/kratos
    networks:
      - intranet

  mailslurper:
    image: oryd/mailslurper:latest-smtps
    ports:
      - "4436:4436"
      - "4437:4437"
    networks:
      - intranet

  postgresd:
    image: postgres:latest
    ports:
        - "5432:5432"
    environment:
        - POSTGRES_DB=kratos
        - POSTGRES_USER=kratos
        - POSTGRES_PASSWORD=secret
    networks:
        - intranet

networks:
  intranet:

volumes:
  kratos-sqlite:
  1. Run docker-compose -f quickstart.yml up
  2. In this scenario, Kratos is using the PostgreSQL database. If we navigate to http://127.0.0.1:4455/auth/registration and try to register an user, an error message should be desplayed. However, the user is created in DB, but the verification email is not sent to MailSlurper. If we look at the logs, the error occurred in Kratos: "pq: value too long for type character varying(255)". The JSON error message (500) returned is: 
    {
"error": {
    "code": 500,
    "message": "pq: value too long for type character varying(255)"
}
}

Server logs

kratos_1                      | time="2020-02-25T09:27:22Z" level=info msg="started handling request" method=POST name="public#http://127.0.0.1:4455/.ory/kratos/public/" remote="172.26.0.7:34870" request="/self-service/browser/flows/registration/strategies/password?request=7c361ad9-4895-475f-9cc6-d87a10ee47b3"
kratos_1                      | time="2020-02-25T09:27:22Z" level=debug msg="A new identity has registered using self-service registration. Running post execution hooks." identity_id=b10a5224-6bb4-4933-8b36-25c040308955
kratos_1                      | time="2020-02-25T09:27:22Z" level=debug msg="Sending out verification code." via=email
kratos_1                      | time="2020-02-25T09:27:22Z" level=debug msg="Sending out verification email." via=email
postgresd_1                   | 2020-02-25 09:27:22.682 UTC [71] ERROR:  value too long for type character varying(255)
postgresd_1                   | 2020-02-25 09:27:22.682 UTC [71] STATEMENT:  INSERT INTO "courier_messages" ("body", "created_at", "id", "recipient", "status", "subject", "type", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8)
kratos_1                      | time="2020-02-25T09:27:22Z" level=warning msg="Encountered login error." credentials_type=password details="pq: value too long for type character varying(255)\ngithub.com/ory/x/sqlcon.HandleError\n\t/go/pkg/mod/github.com/ory/x@v0.0.95/sqlcon/error.go:47\ngithub.com/ory/kratos/persistence/sql.(*Persister).AddMessage\n\t/home/ory/persistence/sql/persister_courier.go:19\ngithub.com/ory/kratos/courier.(*Courier).QueueEmail\n\t/home/ory/courier/courier.go:79\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).sendCodeToKnownAddress.func1\n\t/home/ory/selfservice/flow/verify/sender.go:81\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).run\n\t/home/ory/selfservice/flow/verify/sender.go:99\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).sendCodeToKnownAddress\n\t/home/ory/selfservice/flow/verify/sender.go:80\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).SendCode\n\t/home/ory/selfservice/flow/verify/sender.go:63\ngithub.com/ory/kratos/selfservice/hook.(*Verifier).ExecuteRegistrationPostHook\n\t/home/ory/selfservice/hook/verify.go:31\ngithub.com/ory/kratos/selfservice/flow/registration.(*HookExecutor).PostRegistrationHook\n\t/home/ory/selfservice/flow/registration/hook.go:76\ngithub.com/ory/kratos/selfservice/strategy/password.(*Strategy).handleRegistration\n\t/home/ory/selfservice/strategy/password/registration.go:165\ngithub.com/ory/kratos/session.(*Handler).IsNotAuthenticated.func1\n\t/home/ory/session/handler.go:108\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\ngithub.com/justinas/nosurf.(*CSRFHandler).handleSuccess\n\t/go/pkg/mod/github.com/justinas/nosurf@v0.0.0-20190118163749-6453469bdcc9/handler.go:187\ngithub.com/justinas/nosurf.(*CSRFHandler).ServeHTTP\n\t/go/pkg/mod/github.com/justinas/nosurf@v0.0.0-20190118163749-6453469bdcc9/handler.go:180\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.95/metricsx/middleware.go:261\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.95/reqlog/middleware.go:140\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2007\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2802\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1890\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357" error="pq: value too long for type character varying(255)" login_request="&{7c361ad9-4895-475f-9cc6-d87a10ee47b3 2020-02-25 09:37:18.960865 +0000 +0000 2020-02-25 09:27:18.960866 +0000 +0000 http://127.0.0.1:4455/self-service/browser/flows/registration  map[oidc:0xc0003d9b90 password:0xc0003d9ab0] [] 2020-02-25 09:27:18.962023 +0000 +0000 2020-02-25 09:27:18.962026 +0000 +0000 U5YB8RVmwr1aUAWNFip45skvC6dYJJwpbFWjUV26j9InNx8G8oHqjEbAAaEiK0RcOCYjoAETMLMLNF7/g8U3hA==}"
kratos_1                      | time="2020-02-25T09:27:22Z" level=error msg="An error occurred while handling a request" code=500 debug= details="map[]" error="pq: value too long for type character varying(255)" reason= request-id= status=500 trace="Stack trace: \ngithub.com/ory/x/sqlcon.HandleError\n\t/go/pkg/mod/github.com/ory/x@v0.0.95/sqlcon/error.go:47\ngithub.com/ory/kratos/persistence/sql.(*Persister).AddMessage\n\t/home/ory/persistence/sql/persister_courier.go:19\ngithub.com/ory/kratos/courier.(*Courier).QueueEmail\n\t/home/ory/courier/courier.go:79\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).sendCodeToKnownAddress.func1\n\t/home/ory/selfservice/flow/verify/sender.go:81\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).run\n\t/home/ory/selfservice/flow/verify/sender.go:99\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).sendCodeToKnownAddress\n\t/home/ory/selfservice/flow/verify/sender.go:80\ngithub.com/ory/kratos/selfservice/flow/verify.(*Sender).SendCode\n\t/home/ory/selfservice/flow/verify/sender.go:63\ngithub.com/ory/kratos/selfservice/hook.(*Verifier).ExecuteRegistrationPostHook\n\t/home/ory/selfservice/hook/verify.go:31\ngithub.com/ory/kratos/selfservice/flow/registration.(*HookExecutor).PostRegistrationHook\n\t/home/ory/selfservice/flow/registration/hook.go:76\ngithub.com/ory/kratos/selfservice/strategy/password.(*Strategy).handleRegistration\n\t/home/ory/selfservice/strategy/password/registration.go:165\ngithub.com/ory/kratos/session.(*Handler).IsNotAuthenticated.func1\n\t/home/ory/session/handler.go:108\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\ngithub.com/justinas/nosurf.(*CSRFHandler).handleSuccess\n\t/go/pkg/mod/github.com/justinas/nosurf@v0.0.0-20190118163749-6453469bdcc9/handler.go:187\ngithub.com/justinas/nosurf.(*CSRFHandler).ServeHTTP\n\t/go/pkg/mod/github.com/justinas/nosurf@v0.0.0-20190118163749-6453469bdcc9/handler.go:180\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.95/metricsx/middleware.go:261\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.95/reqlog/middleware.go:140\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/gorilla/context.ClearHandler.func1\n\t/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2007\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2802\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1890\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1357" writer=JSON
kratos_1                      | time="2020-02-25T09:27:22Z" level=info msg="completed handling request" method=POST name="public#http://127.0.0.1:4455/.ory/kratos/public/" remote="172.26.0.7:34870" request="/self-service/browser/flows/registration/strategies/password?request=7c361ad9-4895-475f-9cc6-d87a10ee47b3" status=500 text_status="Internal Server Error" took=406.073648ms

Server configuration

Kratos configuration is the same as in the Quickstart demo project.

Environment

aeneasr commented 4 years ago

This is definitely a bug. We’re currently not running the tests against all DBs, only sqlite and then some basic persistence tests for MySQL etc. Looks like this has caused already two bugs so we probably should start doing that to avoid bugs like these in the future. PostgreSQL is the backend of choice for Kratos and a first class citizen :)

jdelgadoalfonso commented 4 years ago

Field body in courier_messages table is a VARCHAR(255) which is not enough to store body message. I changed the type to TEXT and it works like a charm

aeneasr commented 4 years ago

Ah yeah, looks like the migrations generated TEXT in SQLite and VARCHAR in PostgreSQL. We'll update the migrations to use TEXT for that field.

reidlai commented 4 years ago

I got the same case here

aeneasr commented 4 years ago

@zepatrik can you take this one?