search

ory / kratos

Next-gen identity server replacing your Auth0, Okta, Firebase with hardened security and PassKeys, SMS, OIDC, Social Sign In, MFA, FIDO, TOTP and OTP, WebAuthn, passwordless and much more. Golang, headless, API-first. Available as a worry-free SaaS with the fairest pricing on the market!
https://www.ory.sh/kratos/?utm_source=github&utm_medium=banner&utm_campaign=kratos
Apache License 2.0
11.03k stars 951 forks source link

Connection failed with mailslurper #1669

Closed lucassimon closed 3 years ago

lucassimon commented 3 years ago

Describe the bug

A clear and concise description of what the bug is.

When I setup the kratos v0.7.1-alpha1 and mailslurper on my docker-composer I got an error when the kratos sends an email.

Reproducing the bug

Steps to reproduce the behavior:

  1. Clone this repo: https://github.com/lucassimon/lab-ory-kratos
  2. Run docker-compose up --build
  3. Make API Request to with curl

Fetch register flow

Request

curl -X GET 0.0.0.0:4433/self-service/registration/api -H 'Accept: application/json' | jq

Response

{
  "id": "6e0c9b4a-3d94-428e-ba36-2f7fa3810e68",
  "type": "api",
  "expires_at": "2021-08-20T15:05:09.06896773Z",
  "issued_at": "2021-08-20T14:55:09.06896773Z",
  "request_url": "http://0.0.0.0:4433/self-service/registration/api",
  "ui": {
    "action": "http://local.lab.com/user-svc/public/self-service/registration?flow=6e0c9b4a-3d94-428e-ba36-2f7fa3810e68",
    "method": "POST",
    "nodes": [
      {
        "type": "input",
        "group": "default",
        "attributes": {
          "name": "csrf_token",
          "type": "hidden",
          "value": "",
          "required": true,
          "disabled": false
        },
        "messages": [],
        "meta": {}
      },
      {
        "type": "input",
        "group": "password",
        "attributes": {
          "name": "traits.email",
          "type": "email",
          "disabled": false
        },
        "messages": [],
        "meta": {
          "label": {
            "id": 1070002,
            "text": "E-Mail",
            "type": "info"
          }
        }
      },
      {
        "type": "input",
        "group": "password",
        "attributes": {
          "name": "password",
          "type": "password",
          "required": true,
          "disabled": false
        },
        "messages": [],
        "meta": {
          "label": {
            "id": 1070001,
            "text": "Password",
            "type": "info"
          }
        }
      },
      {
        "type": "input",
        "group": "password",
        "attributes": {
          "name": "method",
          "type": "submit",
          "value": "password",
          "disabled": false
        },
        "messages": [],
        "meta": {
          "label": {
            "id": 1040001,
            "text": "Sign up",
            "type": "info",
            "context": {}
          }
        }
      }
    ]
  }
}

Submit register flow

Request

curl -X POST "http://0.0.0.0:4433/self-service/registration?flow=6e0c9b4a-3d94-428e-ba36-2f7fa3810e68" -H "Accept: application/json" -H "Content-Type: application/json" -d '{"traits":{"email": "foo@bar.com"}, "method": "password", "password":"foo_bar_123"}' | jq

Response

{
  "session_token": "vJI1C7Xq1Szp0hl7OJmjVtPlnkw7mfjw",
  "session": {
    "id": "0c981101-a38c-4b8e-ba8c-bd64f53475ee",
    "active": true,
    "expires_at": "2021-08-21T14:58:57.576680924Z",
    "authenticated_at": "2021-08-20T14:58:57.594350035Z",
    "issued_at": "2021-08-20T14:58:57.576687376Z",
    "identity": {
      "id": "52f1ae29-7d80-475d-9dc5-172fdcb62eb5",
      "schema_id": "default",
      "schema_url": "http://local.lab.com/user-svc/public/schemas/default",
      "state": "active",
      "state_changed_at": "2021-08-20T14:58:57.560358941Z",
      "traits": {
        "email": "foo@bar.com"
      },
      "verifiable_addresses": [
        {
          "id": "53679473-4f0d-4c6d-8a96-1f78f9a6114d",
          "value": "foo@bar.com",
          "verified": false,
          "via": "email",
          "status": "sent",
          "verified_at": null,
          "created_at": "2021-08-20T14:58:57.564945Z",
          "updated_at": "2021-08-20T14:58:57.564945Z"
        }
      ],
      "recovery_addresses": [
        {
          "id": "3b21a280-38f0-45ce-80eb-a582f0cd66a8",
          "value": "foo@bar.com",
          "via": "email",
          "created_at": "2021-08-20T14:58:57.568329Z",
          "updated_at": "2021-08-20T14:58:57.568329Z"
        }
      ],
      "created_at": "2021-08-20T14:58:57.561832Z",
      "updated_at": "2021-08-20T14:58:57.561832Z"
    }
  },
  "identity": {
    "id": "52f1ae29-7d80-475d-9dc5-172fdcb62eb5",
    "schema_id": "default",
    "schema_url": "http://local.lab.com/user-svc/public/schemas/default",
    "state": "active",
    "state_changed_at": "2021-08-20T14:58:57.560358941Z",
    "traits": {
      "email": "foo@bar.com"
    },
    "verifiable_addresses": [
      {
        "id": "53679473-4f0d-4c6d-8a96-1f78f9a6114d",
        "value": "foo@bar.com",
        "verified": false,
        "via": "email",
        "status": "sent",
        "verified_at": null,
        "created_at": "2021-08-20T14:58:57.564945Z",
        "updated_at": "2021-08-20T14:58:57.564945Z"
      }
    ],
    "recovery_addresses": [
      {
        "id": "3b21a280-38f0-45ce-80eb-a582f0cd66a8",
        "value": "foo@bar.com",
        "via": "email",
        "created_at": "2021-08-20T14:58:57.568329Z",
        "updated_at": "2021-08-20T14:58:57.568329Z"
      }
    ],
    "created_at": "2021-08-20T14:58:57.561832Z",
    "updated_at": "2021-08-20T14:58:57.561832Z"
  }
}

Server logs

mailslurper_1     | time="2021-08-20T17:20:41Z" level=info msg="Connection closed" connection="192.168.48.3:34916" who="Connection Manager"
mailslurper_1     | time="2021-08-20T17:20:45Z" level=info msg="Worker 207 queued to handle connections from 192.168.48.3:34920" who="SMTP Server Pool"
mailslurper_1     | time="2021-08-20T17:20:45Z" level=info msg="Connection closed" connection="192.168.48.3:59600" who="Connection Manager"
mailslurper_1     | time="2021-08-20T17:20:55Z" level=info msg="Connection closed" connection="192.168.48.3:34920" who="Connection Manager"
iam-svc_1         | time=2021-08-20T17:20:55Z level=error msg=Unable to send email using SMTP connection. audience=application error=map[message:read tcp 192.168.48.3:34920->192.168.48.2:1025: i/o timeout] message_from=no-reply@ory.kratos.sh service_name=Ory Kratos service_version=v0.7.1-alpha.1 smtp_server=mailslurper:1025 smtp_ssl_enabled=false
mailslurper_1     | time="2021-08-20T17:21:03Z" level=info msg="Worker 208 queued to handle connections from 192.168.48.3:34930" who="SMTP Server Pool"
mailslurper_1     | time="2021-08-20T17:21:03Z" level=info msg="Connection closed" connection="192.168.48.3:60474" who="Connection Manager"
iam-svc_1         | time=2021-08-20T17:21:13Z level=error msg=Unable to send email using SMTP connection. audience=application error=map[message:read tcp 192.168.48.3:34930->192.168.48.2:1025: i/o timeout] message_from=no-reply@ory.kratos.sh service_name=Ory Kratos service_version=v0.7.1-alpha.1 smtp_server=mailslurper:1025 smtp_ssl_enabled=false
mailslurper_1     | time="2021-08-20T17:21:13Z" level=info msg="Connection closed" connection="192.168.48.3:34930" who="Connection Manager"
mailslurper_1     | time="2021-08-20T17:21:26Z" level=info msg="Worker 209 queued to handle connections from 192.168.48.3:34948" who="SMTP Server Pool"
mailslurper_1     | fatal error: concurrent map read and map write
mailslurper_1     | 
mailslurper_1     | goroutine 32 [running]:
mailslurper_1     | runtime.throw(0xb68799, 0x21)
mailslurper_1     |     /usr/local/go/src/runtime/panic.go:774 +0x72 fp=0xc0008f7b28 sp=0xc0008f7af8 pc=0x4354a2
mailslurper_1     | runtime.mapaccess2_faststr(0xaa92c0, 0xc0005afd70, 0xc00049ac00, 0x12, 0xc000073b00, 0xc0008f7d38)
mailslurper_1     |     /usr/local/go/src/runtime/map_faststr.go:116 +0x48f fp=0xc0008f7b98 sp=0xc0008f7b28 pc=0x41a3cf
mailslurper_1     | github.com/mailslurper/mailslurper/pkg/mailslurper.(*ConnectionManager).connectionExistsInPool(0xc0000ba0c0, 0xdacf20, 0xc000043180, 0xc000073c38)
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/ConnectionManager.go:90 +0x7b fp=0xc0008f7bd8 sp=0xc0008f7b98 pc=0x915c0b
mailslurper_1     | github.com/mailslurper/mailslurper/pkg/mailslurper.(*ConnectionManager).Close(0xc0000ba0c0, 0xdacf20, 0xc000043180, 0x0, 0x1)
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/ConnectionManager.go:77 +0x46 fp=0xc0008f7c48 sp=0xc0008f7bd8 pc=0x915946
mailslurper_1     | github.com/mailslurper/mailslurper/pkg/mailslurper.NewConnectionManager.func1(0xc00009c1e0, 0xc0000ba0c0, 0xc0005b9500, 0xda8360, 0xc0000ba000)
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/ConnectionManager.go:54 +0x186 fp=0xc0008f7fb8 sp=0xc0008f7c48 pc=0x92af16
mailslurper_1     | runtime.goexit()
mailslurper_1     |     /usr/local/go/src/runtime/asm_amd64.s:1357 +0x1 fp=0xc0008f7fc0 sp=0xc0008f7fb8 pc=0x462851
mailslurper_1     | created by github.com/mailslurper/mailslurper/pkg/mailslurper.NewConnectionManager
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/ConnectionManager.go:48 +0x100
mailslurper_1     | 
mailslurper_1     | goroutine 1 [chan receive, 155 minutes]:
mailslurper_1     | main.main()
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/cmd/mailslurper/mailslurper.go:85 +0x4b1
mailslurper_1     | 
mailslurper_1     | goroutine 19 [syscall, 155 minutes]:
mailslurper_1     | os/signal.signal_recv(0x0)
mailslurper_1     |     /usr/local/go/src/runtime/sigqueue.go:147 +0x9c
mailslurper_1     | os/signal.loop()
mailslurper_1     |     /usr/local/go/src/os/signal/signal_unix.go:23 +0x22
mailslurper_1     | created by os/signal.init.0
mailslurper_1     |     /usr/local/go/src/os/signal/signal_unix.go:29 +0x41
mailslurper_1     | 
mailslurper_1     | goroutine 28 [select, 155 minutes]:
mailslurper_1     | database/sql.(*DB).connectionOpener(0xc0001763c0, 0xda8360, 0xc0001475c0)
mailslurper_1     |     /usr/local/go/src/database/sql/sql.go:1052 +0xe8
mailslurper_1     | created by database/sql.OpenDB
mailslurper_1     |     /usr/local/go/src/database/sql/sql.go:722 +0x15d
mailslurper_1     | 
mailslurper_1     | goroutine 29 [select, 155 minutes]:
mailslurper_1     | database/sql.(*DB).connectionResetter(0xc0001763c0, 0xda8360, 0xc0001475c0)
mailslurper_1     |     /usr/local/go/src/database/sql/sql.go:1065 +0xfb
mailslurper_1     | created by database/sql.OpenDB
mailslurper_1     |     /usr/local/go/src/database/sql/sql.go:723 +0x193
mailslurper_1     | 
mailslurper_1     | goroutine 33 [select, 155 minutes]:
mailslurper_1     | github.com/mailslurper/mailslurper/pkg/mailslurper.(*SMTPListener).Dispatch.func1(0xc00008c000, 0xda8360, 0xc0000ba000)
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/SMTPListener.go:112 +0x17c
mailslurper_1     | created by github.com/mailslurper/mailslurper/pkg/mailslurper.(*SMTPListener).Dispatch
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/SMTPListener.go:108 +0x57
mailslurper_1     | 
mailslurper_1     | goroutine 50 [runnable]:
mailslurper_1     | context.(*cancelCtx).Done(0xc0000ba000, 0xdacf20)
mailslurper_1     |     /usr/local/go/src/context/context.go:324 +0xef
mailslurper_1     | github.com/mailslurper/mailslurper/pkg/mailslurper.(*SMTPListener).Dispatch.func2(0xda8360, 0xc0000ba000, 0xc00008c000)
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/SMTPListener.go:131 +0x4c
mailslurper_1     | created by github.com/mailslurper/mailslurper/pkg/mailslurper.(*SMTPListener).Dispatch
mailslurper_1     |     /go/src/github.com/mailslurper/mailslurper/pkg/mailslurper/SMTPListener.go:128 +0x8d
mailslurper_1     | 
mailslurper_1     | goroutine 51 [IO wait, 155 minutes]:

Server configuration

version: v0.7.1-alpha.1

dsn: memory

serve:
  public:
    base_url: ${GATEWAY_SVC_URL}/user-svc/public
    port: 4433
    cors:
      enabled: true
      allowed_origins:
        - ${GATEWAY_SVC_URL}
      allowed_methods:
        - GET
      allowed_headers:
        - Content-Type
        - Accept
        - Cookie
      exposed_headers:
        - Content-Type
        - Set-Cookie
  admin:
    base_url: ${GATEWAY_SVC_URL}/user-svc/admin
    port: 4434

selfservice:
  default_browser_return_url: ${GATEWAY_SVC_URL}/
  whitelisted_return_urls:
    - ${GATEWAY_SVC_URL}

  methods:
    password:
      enabled: true

  flows:
    error:
      ui_url: ${GATEWAY_SVC_URL}/auth/error

    settings:
      ui_url: ${GATEWAY_SVC_URL}/auth/settings
      privileged_session_max_age: 15m

    recovery:
      enabled: true
      ui_url: ${GATEWAY_SVC_URL}/auth/recovery

    verification:
      enabled: true
      ui_url: ${GATEWAY_SVC_URL}/auth/verify
      after:
        default_browser_return_url: ${GATEWAY_SVC_URL}/

    logout:
      after:
        default_browser_return_url: ${GATEWAY_SVC_URL}/auth/login

    login:
      ui_url: ${GATEWAY_SVC_URL}/auth/login
      lifespan: 10m

    registration:
      lifespan: 10m
      ui_url: ${GATEWAY_SVC_URL}/auth/register
      after:
        password:
          hooks:
            - hook: session

log:
  level: debug
  format: text
  leak_sensitive_values: true

secrets:
  cookie:
    - strong-cookie
  default:
    - foobarfizzbuzzmarcopolo

hashers:
  argon2:
    parallelism: 1
    memory: 128MB
    iterations: 2
    salt_length: 16
    key_length: 16

Expected behavior

I don't receive any email. Connection closed/fail, even the services are in the same network.

docker-compose.yaml

  iam-svc:
    depends_on:
      - kratos-migrate
    build: .
    restart: unless-stopped
    environment:
      DATABASE_URL_DECODED: postgres://kratos:secret@postgresd:5432/kratos?sslmode=disable&max_conns=20&max_idle_conns=4
      SMTP_URL: smtps://test:test@mailslurper:1025/?skip_ssl_verify=true
      LOG_LEVEL: debug
      GATEWAY_SVC_URL: http://local.lab.com
    command:
      serve -c /home/ory/kratos.yml --dev --watch-courier
    ports:
      - 4433:4433
      - 4434:4434
    networks:
      - default
      - lab-net

  postgresd:
    image: postgres:9.6
    environment:
      - POSTGRES_USER=kratos
      - POSTGRES_PASSWORD=secret
      - POSTGRES_DB=kratos

  mailslurper:
    image: oryd/mailslurper:latest-smtps
    ports:
      - "4436:4436"
      - "4437:4437"
    networks:
      - lab-net
networks:
  lab-net:
    name: mylab-svc_lab-net
    external: true

Environment

aeneasr commented 3 years ago

Looks like a bug in mailslurper, not here. Restarting the env should fix it :)

lucassimon commented 3 years ago

I don't know what happens

Screenshot from 2021-08-26 16-02-32

After restart

restart_mailsluper

Another connection fail

Screenshot from 2021-08-26 16-04-04

aeneasr commented 3 years ago

Unfortunately I don’t know either. It works fine repeatedly in our CI and all local environments. Maybe it’s a system issue, maybe a docker issue - I don’t know. However, it is not a bug i. this project which is why I will be closing this issue. I hope you understand and find a way to resolve this. Maybe someone on Stack Overflow can help!

lucassimon commented 2 years ago

Hello @aeneasr I know that is not a bug in Kratos. I solve it using another fake smtp server: Mailhog.

Some changes in my config:

  iam-svc:
    depends_on:
      - kratos-migrate
    build: .
    restart: unless-stopped
    environment:
      DATABASE_URL_DECODED: postgres://kratos:secret@postgresd:5432/kratos?sslmode=disable&max_conns=20&max_idle_conns=4
      SMTP_URL: smtp://mailhog:1025

  mailhog:
    image: mailhog/mailhog:latest
    ports:
      - 1025:1025
      - 8025:8025
    networks:
      - lab-net

Because of that dependency with smtp server that I created too the issue: https://github.com/ory/kratos/issues/1668

    "messages": [
      {
        "id": 1070001,
        "text": "An email containing a verification link has been sent to the email address you provided.",
        "type": "info",
        "context": {}
      }
    ]
  },
  "state": "sent_email"
}
aeneasr commented 2 years ago

Awesome! :)