search

goharbor / harbor-helm

The helm chart to deploy Harbor
Apache License 2.0
1.2k stars 759 forks source link

"Reset Password" dialog reports "...internal server errors..." on Send action #240

Closed javajon closed 5 years ago

javajon commented 5 years ago

Have Harbor Helm chart v1.0.1 running healthy on Kubernetes DigitalOcean (DOKS) v1.14.0. All deployments/pods/services appear healthy. We can push and pull images from the registry.

Pods status reports healthy:

$ kubectl get pods -n harbor
NAME                                           READY   STATUS    RESTARTS   AGE
harbor-harbor-chartmuseum-d95f8998c-r29gs      1/1     Running   0          9d
harbor-harbor-clair-8bbb65b77-4cqlt            1/1     Running   1          9d
harbor-harbor-core-7cb9978998-t858f            1/1     Running   1          9d
harbor-harbor-database-0                       1/1     Running   0          9d
harbor-harbor-jobservice-d479bb57d-62lb7       1/1     Running   1          9d
harbor-harbor-notary-server-b56dc59f8-pxg7d    1/1     Running   2          9d
harbor-harbor-notary-signer-5f7977d668-kh6pq   1/1     Running   2          9d
harbor-harbor-portal-5c8f5d49b8-lqfcc          1/1     Running   0          9d
harbor-harbor-redis-0                          1/1     Running   0          9d
harbor-harbor-registry-5d89b956d9-sbxs7        2/2     Running   0          9d

I started to work with the Email configuration. The "Test Mail Server" button correctly reports "Connection to mail server is verified." when all the right email server information is entered:

Email Server: smtp.gmail.com
Email Server Port: 465
Email User Name: admin@mycompany.com
Email Password: [valid and verified Gmail "App Password"]
From Email: admin <admin@mycompany.com>
Email SSL: [Checked]
Verify Certificate: [Checked]

For double checking, I also verified this curl command successfully sends an email using the same configurations.

EMAIL_ADMIN=admin@mycompany.com
EMAIL_ADMIN_PW=[valid and verified Gmail "App Password"]
TO_EMAIL='me@mycompany.com'

curl --url "smtps://smtp.gmail.com:465" -v \
  --ssl-reqd \
  --mail-from "$EMAIL_ADMIN" \
  --mail-rcpt "$TO_EMAIL" \
  --upload-file mail.txt \
  --user "$EMAIL_ADMIN:$EMAIL_ADMIN_PW"

Everything so far seems healthy. However, the purpose of the email feature is to send password reset emails. On the Harbor Sign-In page clicking on the "Forgot Password" action takes us to the "Reset Password" dialog.

  1. When a valid email that is already associated with a Harbor user id (e.g. as above me@mycompany.com) is entered and sent, the dialog shows this error message: "We are unable to perform your action because internal server errors have occurred."

  2. When a bogus email like foo@mycompany.com is entered, this error message appears: "Your request cannot be completed because the object does not exist."

I'm most interest in solving the first issue and seeking advice on the next steps to diagnose the problem. In the Harbor reset password TS code it appears the HTTPS Status 500 from some server is associated with the error message SERVER_ERROR="We are unable to perform your action because internal server errors have occurred." There is nothing in the /var/log directory of the running harbor-core pod/container.

Looking for advice on techniques to find the problem(s) or gather artifacts/logs to attach to this issue.

javajon commented 5 years ago

Additional observation: Every ~5 seconds the harbor-core pod log reports.

2019-05-24T21:09:53Z [DEBUG] [/core/filter/security.go:233]: OIDC CLI modifer only handles request by docker CLI or helm CLI
2019-05-24T21:09:53Z [DEBUG] [/core/filter/security.go:491]: can not get user information from session
2019-05-24T21:09:53Z [DEBUG] [/core/filter/security.go:560]: user information is nil
2019-05-24T21:09:53Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-24T21:09:53Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-24T21:09:53Z [DEBUG] [/core/filter/security.go:574]: using local database project manager
2019-05-24T21:09:53Z [DEBUG] [/core/filter/security.go:576]: creating local database security context...
2019/05/24 21:09:53 [D] [server.go:2619] |     10.244.3.1| 200 |   3.350602ms|   match| GET      /api/ping   r:/api/ping

Not sure what this is or if it's related.

ywk253100 commented 5 years ago

There should be some logs in the core component to show the detail of the internal error. Could you retry the operation and catch the output of the logs of core?

ywk253100 commented 5 years ago

Or you can just upload all logs of the core

javajon commented 5 years ago

As requested, tried the Send Password Reset request again and captured the tail of the log. The top block in the log repeats, but the last ~dozen lines appear to be propagated by the password reset request:

2019/05/28 13:29:13 [D] [server.go:2619] |     10.244.3.1| 200 |     2.8118ms|   match| GET      /api/ping   r:/api/ping
2019-05-28T13:29:19Z [DEBUG] [/core/filter/security.go:233]: OIDC CLI modifer only handles request by docker CLI or helm CLI
2019-05-28T13:29:19Z [DEBUG] [/core/filter/security.go:491]: can not get user information from session
2019-05-28T13:29:19Z [DEBUG] [/core/filter/security.go:560]: user information is nil
2019-05-28T13:29:19Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-28T13:29:19Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-28T13:29:19Z [DEBUG] [/core/filter/security.go:574]: using local database project manager
2019-05-28T13:29:19Z [DEBUG] [/core/filter/security.go:576]: creating local database security context...
2019/05/28 13:29:19 [D] [server.go:2619] |     10.244.3.1| 200 |   4.263778ms|   match| GET      /api/ping   r:/api/ping
2019-05-28T13:29:23Z [DEBUG] [/core/filter/security.go:233]: OIDC CLI modifer only handles request by docker CLI or helm CLI
2019-05-28T13:29:23Z [DEBUG] [/core/filter/security.go:491]: can not get user information from session
2019-05-28T13:29:23Z [DEBUG] [/core/filter/security.go:560]: user information is nil
2019-05-28T13:29:23Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-28T13:29:23Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-28T13:29:23Z [DEBUG] [/core/filter/security.go:574]: using local database project manager
2019-05-28T13:29:23Z [DEBUG] [/core/filter/security.go:576]: creating local database security context...
2019/05/28 13:29:23 [D] [server.go:2619] |     10.244.3.1| 200 |   4.027125ms|   match| GET      /api/ping   r:/api/ping
2019-05-28T13:29:25Z [DEBUG] [/core/filter/security.go:233]: OIDC CLI modifer only handles request by docker CLI or helm CLI
2019-05-28T13:29:25Z [DEBUG] [/core/filter/security.go:491]: can not get user information from session
2019-05-28T13:29:25Z [DEBUG] [/core/filter/security.go:560]: user information is nil
2019-05-28T13:29:25Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-28T13:29:25Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-28T13:29:25Z [DEBUG] [/core/filter/security.go:574]: using local database project manager
2019-05-28T13:29:25Z [DEBUG] [/core/filter/security.go:576]: creating local database security context...
2019-05-28T13:29:25Z [ERROR] [/common/config/manager.go:192]: failed to get key email_identity, error: the configure value is not set
2019-05-28T13:29:25Z [DEBUG] [/common/utils/email/mail.go:92]: establishing TCP connection with smtp.gmail.com:465 ...
2019-05-28T13:29:25Z [DEBUG] [/common/utils/email/mail.go:105]: establishing SSL/TLS connection with smtp.gmail.com:465 ...
2019-05-28T13:29:25Z [DEBUG] [/common/utils/email/mail.go:117]: creating SMTP client for smtp.gmail.com ...
2019-05-28T13:29:25Z [DEBUG] [/common/utils/email/mail.go:140]: authenticating the client...

This instance of Harbor was installed using the Helm chart goharbor/harbor-helm. Here are details of the provisioning script that drives the Helm install.

Core pod has these env vars:

CORE_URL (harbor-harbor-core): http://harbor-harbor-core
POSTGRESQL_USERNAME (harbor-harbor-core): postgres
WITH_CHARTMUSEUM (harbor-harbor-core): true
_REDIS_URL (harbor-harbor-core): harbor-harbor-redis:6379,100,
TOKEN_SERVICE_URL (harbor-harbor-core): http://harbor-harbor-core/service/token
CHART_REPOSITORY_URL (harbor-harbor-core): http://harbor-harbor-chartmuseum
CLAIR_DB (harbor-harbor-core): postgres
CLAIR_DB_SSLMODE (harbor-harbor-core): disable
CLAIR_DB_USERNAME (harbor-harbor-core): postgres
JOBSERVICE_URL (harbor-harbor-core): http://harbor-harbor-jobservice
POSTGRESQL_HOST (harbor-harbor-core): harbor-harbor-database
REGISTRY_URL (harbor-harbor-core): http://harbor-harbor-registry:5000
CLAIR_HEALTH_CHECK_SERVER_URL (harbor-harbor-core): http://harbor-harbor-clair:6061
CLAIR_URL (harbor-harbor-core): http://harbor-harbor-clair:6060
PORTAL_URL (harbor-harbor-core): http://harbor-harbor-portal
REGISTRYCTL_URL (harbor-harbor-core): http://harbor-harbor-registry:8080
WITH_CLAIR (harbor-harbor-core): true
CLAIR_DB_PORT (harbor-harbor-core): 5432
EXT_ENDPOINT (harbor-harbor-core): https://harbor.mydomain.com
WITH_NOTARY (harbor-harbor-core): true
app.conf (harbor-harbor-core): 
appname = Harbor
runmode = dev
enablegzip = true

[dev]
httpport = 8080
REGISTRY_STORAGE_PROVIDER_NAME (harbor-harbor-core): filesystem
DATABASE_TYPE (harbor-harbor-core): postgresql
LOG_LEVEL (harbor-harbor-core): debug
NOTARY_URL (harbor-harbor-core): http://harbor-harbor-notary-server:4443
POSTGRESQL_DATABASE (harbor-harbor-core): registry
CFG_EXPIRATION (harbor-harbor-core): 5
CHART_CACHE_DRIVER (harbor-harbor-core): redis
CONFIG_PATH (harbor-harbor-core): /etc/core/app.conf
POSTGRESQL_SSLMODE (harbor-harbor-core): disable
CLAIR_DB_HOST (harbor-harbor-core): harbor-harbor-database
POSTGRESQL_PORT (harbor-harbor-core): 5432
SYNC_REGISTRY (harbor-harbor-core): false
_REDIS_URL_REG (harbor-harbor-core): redis://harbor-harbor-redis:6379/2
ywk253100 commented 5 years ago

It shouldn't hang on authenticating the client..., there should be more logs. Could you upload all logs?

javajon commented 5 years ago

Agreed, Harbor core log attached.

harbor-core.log

It looks like the associated log events are:

2019-05-29T13:09:51Z [DEBUG] [/common/utils/email/mail.go:140]: authenticating the client...
2019-05-29T13:09:51Z [DEBUG] [/common/utils/email/mail.go:155]: create smtp client successfully
2019-05-29T13:09:51Z [ERROR] [/core/controllers/base.go:225]: Send email failed: 555 5.5.2 Syntax error. a64sm5815570qkd.73 - gsmtp
2019-05-29T13:09:53Z [DEBUG] [/core/filter/security.go:233]: OIDC CLI modifer only handles request by docker CLI or helm CLI
2019-05-29T13:09:53Z [DEBUG] [/core/filter/security.go:491]: can not get user information from session
2019-05-29T13:09:53Z [DEBUG] [/core/filter/security.go:560]: user information is nil
2019-05-29T13:09:53Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set
2019-05-29T13:09:53Z [ERROR] [/common/config/manager.go:192]: failed to get key admiral_url, error: the configure value is not set

Guessing, gsmtp error 555 may perhaps related to the malformation of the email string data in the perhaps required form: Recipient Name <myname@example.com> The email I'm providing is a valid email and is of one of the users in my Harbor user's list. As expected, the web form for password reset request only allows myname@example.com.

javajon commented 5 years ago

Perhaps the method SendResetEmail() has not been tested with Google email server requirements via gsmtp?

Should an issue be opened in Harbor?

ywk253100 commented 5 years ago

@javajon We didn't verify it against gsmtp server. Seems it's related with the display name. Could you verify it in your environment? As the email sending function is in a separate package here https://github.com/goharbor/harbor/blob/master/src/common/utils/email/mail.go#L29, so maybe you can call it directly by passing your parameters.

If it works, very appreciate that if you can submit a PR to fix this.

javajon commented 5 years ago

@ywk253100

Indeed, found what causes the problem. Following your suggestion, I took the mail.go code and wrote a corresponding mail_test_go. With this, both tests pass with the TestPing passing and the TestSend passes and sends an email received in my inbox. The important string form for the FROM value is the culprit.

var from = "admin admin@mycompany.com"

It must be of the form"RecipientName myname@example.com" with the space between the recipient and the actual email. One might think that it should be "Recipient Name <myname@example.com>", with the brackets as specified in the spec RFC 2821, but including the brackets also cause the same 555 error. Perhaps the brackets are added later in the logic. Another reference about this.

Here is the passing test code with gsmtp / Google gmail server.

package email

import "testing"

var addr = "smtp.gmail.com:465"
var identity = "admin@mycompany.com"
var username = "admin@mycompany.com"
var password = "redacted"
var timeout = 30
var tls = true
var insecure = false

var from = "admin admin@mycompany.com"
var to = []string {"me@mycompany.com"}
var subject = "From Go TestSend"
var message = "Z Bodet."

func TestPing(t *testing.T) {
  if err := Ping(addr, identity, username, password, timeout, tls, insecure); err != nil {
    t.Error("Ping failed.", err)
  }
}

func TestSend(t *testing.T) {
  if err := Send(addr, identity, username, password, timeout, tls, insecure, from, to, subject, message); err != nil {
    t.Error("Send failed.", err)
  }
}

If you agree with these findings, I'll work on a PR.

ywk253100 commented 5 years ago

If the format of FROM is the root cause of this issue, I think you can modify the property on web portal of Harbor with system administrator user directly and we don't need any fixes, is it correct?

javajon commented 5 years ago

Yes, this worked. Once the "Email from *" field had this correct format the feature performed correctly. Once I put the value in as exactly:

name name@mycompany.com

it worked. Fields values such as name@mycompany.com or "name <name@mycompany.com>" will generate these "internal server errors" and most people will not understand this. The UI definitely needs a design improvement with some validation to ensure the data is valid. It's also confusing to me why the dialog has both an "Email Username" and "Email From" field. All these fields need some sort of validation.

Should I create an issue in Harbor with this UI recommendation?

ywk253100 commented 5 years ago

The Username and Password are used to do the authentication while the From specifies the email from who it is sent, they can be different.

I think the implementations are different for different SMTP servers, we cannot cover all cases easily. How about submitting a PR to record this issue in the user guide https://github.com/goharbor/harbor/blob/master/docs/user_guide.md#managing-email-settings?