Pow: Confirmation issue in production with version 1.0.13

[albertoramires]

Haven't been receiving any confirmation emails on user creation since I've upgraded from 1.0.12 to 1.0.13.

Confirmation through user update works just fine, all other emails work just fine, version 1.0.12 is completely fine and even using Bamboo.SendGridAdapter on local env with production api key gets my emails delivered just fine as well. It's just user creation on prod that isn't working.

If I debug production I receive the message "Sending email with Bamboo.SendGridAdapter", but no mail is actually sent out.

Does anyone else have this issue?

[danschultzer]

Sounds like an issue in sendgrid, since it’s pushed successfully to the sendgrid API. You should check the statistics dashboard in your sendgrid account to see why the e-mail doesn’t get delivered: https://sendgrid.com/docs/glossary/drops/

[albertoramires]

@danschultzer Problem is there were no drops, although I get the debug message the email isn't on Sendgrid, it's really strange because I'm not getting anything logged after that message even with def process(email), do: deliver_now(email, response: true) |> inspect() |> Logger.info().

[danschultzer]

Just looked it up, and the debug message happens no matter if the email could be delivered or not: https://github.com/thoughtbot/bamboo/blob/214f5f3e3be51e15d7c2d4c7449fe1d48a6aa472/lib/bamboo/mailer.ex#L130

Looking at the sendgrid api call it may ignore some errors:

https://github.com/thoughtbot/bamboo/blob/214f5f3e3be51e15d7c2d4c7449fe1d48a6aa472/lib/bamboo/adapters/send_grid_adapter.ex#L38-L54

No idea why this only occurs after you upgraded, and only happens in production. I suspect it’s something unrelated to Pow, but will look into the 1.0.13 changes just to be sure.

[albertoramires]

I suspected it was unrelated to Pow as well so after two hours of changing/testing options I ended changing back to 1.0.12 and the problem was fixed. It could still just be an issue on my end though.

[danschultzer]

That’s frustrating. The major change in 1.0.13 is in the e-mail change logic. These are the relevant changes from the changelog:

• Updated PowEmailConfirmation.Ecto.Schema.changeset/3 so; (#259)
  
  
  
  • when :email is identical to :unconfirmed_email it won't generate new :email_confirmation_token
  
  
  • when :email is identical to the persisted :email value both :email_confirmation_token and :unconfirmed_email will be set to nil
  
  
  • when there is no :email value in the params nothing happens
  
  
• Fixed bug in PowEmailConfirmation.Phoenix.ControllerCallbacks.send_confirmation_email/2 where the confirmation e-mail wasn't send to the updated e-mail address (#256)

If this is Pow, then it may be the last change, which fixed a bug where the confirmation e-mail was send to the current e-mail rather than the updated one.

[sensiblearts]

I think that the same thing is happening with Swoosh and AmazonSES, for me. Which suggests it's a Pow issue. (Reset email works fine.)

  def cast(%{user: user, subject: subject, text: text, html: html} = params) do
    Swoosh.Email.new()
    |> to({"", user.email})
    |> from({"GardenJournal.App", "[email protected]"})
    |> subject(subject)
    |> html_body(html)
    |> text_body(text)
    |> IO.inspect
  end

  def process(email) do
    IO.puts "DELIVERING EMAIL"
    deliver(email)
  end

When I sign up (or try to sign in afterward) to trigger a confirmation:

Pow.Mailer.cast is being called (inspected mail Map is in the log).

But Pow.Mailer.process/1 is not being called (no "DELIVERING MAIL" in the log).

..., which is very strange, because it's called in a pipe and no errors in the log:

def deliver(conn, email) do
    config = Plug.fetch_config(conn)
    mailer = Config.get(config, :mailer_backend) || raise_no_mailer_backend_set()

    email
    |> mailer.cast()
    |> mailer.process()
  end

Stumped.

Also, I confirm that downgrading to 1.0.12 works fine.

[danschultzer]

Do you still get redirected not signed in, and get the You'll need to confirm your e-mail before you can sign in. An e-mail confirmation link has been sent to you. flash message?

FYI here's the diff: https://github.com/danschultzer/pow/compare/v1.0.12...v1.0.13

Also, this seems to only happen in prod and it even works locally with the same api keys from what @albertoramires says. I'll review the diff carefully to see what could have triggered this issue.

[sensiblearts]

Yes, v1.0.13 will redirect with flash saying "... confirmation link has been sent..."; and, mine worked locally, too.

[danschultzer]

I have made a prod release using Pow v1.0.13, Swoosh and SendGrid. It works as expected, and IO.inspect/1 in both cast/1 and process/1 works.

[sensiblearts]

I wonder if this could be a build issue; perhaps we should compare how @danschultzer , @albertoramires and I am doing the release:

I (@sensiblearts) am not using a vm for building; I use mix release on my laptop in Windows WSL, Ubuntu 18.04; then I push it out to DigitalOcean Ubuntu 18.04; hence, both x86_64. Specifically:

mix clean
source .env
MIX_ENV=prod mix release.init
MIX_ENV=prod mix release beta1
cd /tmp
tar -czvf oiv_beta1.tar.gz -C /mnt/c/Users/...../beta1 .

And then Ansible script to untar the results on the server and restart.

(BTW Dan, Thank you!)

[danschultzer]

It would be best if you can make it reproducible (e.g. create a demo repo on GH).

I've been setting up a brand new Phoenix app with Pow and Swoosh enabling email confirmation. Then I built a production release MIX_ENV=prod mix release and ran it locally to test it out _build/prod/rel/pow_demo/bin/pow_demo start.

@sensiblearts if you start the release locally do you still experience the same issue?

[sensiblearts]

@danschultzer , you make me feel old when you suggest the obvious that I'm overlooking :-)

When I run the release locally with start it crashes because of Que, even for v1.0.12:

12:46:18.021 [info] Application que exited: Que.start(:normal, []) returned an error: shutdown: failed to start child: Que.ServerSupervisor
    ** (EXIT) an exception was raised:
        ** (Memento.Error) Transaction Failed with: {:no_exists, Que.Persistence.Mnesia.DB.Jobs}
 ...

(I had some code in for starting Que and Memento etc manually amd _initializing its file_, but I removed that and went back to letting the application start it when I added the new MnesiaClusterSupervisor code. I could put that manual code back, but it would be a waste of time. See below.)

I've not yet tested v.1.0.13 locally, but I think I need to _abandon using Que first_.

So, rather than pursue this, I will switch to a different job queue, perhaps Honeydew, because Honeydew is currently working with multi-node Mnesia, wherease Que does not yet have multi-node.

_I was planning to move away from Que after I got multi-node Pow working, but now I realize Que may prevent that!_

@danschultzer : Do you think it is worth time studying the Que issue as it relates to Pow, or should we just find a good queue that works with Pow and recommend that one?

Also, if you were designing a system, would you try to use Mnesia for both queue and Pow cache, or is that asking for headaches? (I could switch to postgres or add redis.)

Thanks so much.

@albertoramires , have you run your production release locally yet? My guess is that, what you and I have in common is we're both using some other library that uses Mnesia, and it's interfering with Pow's cache..?

[Schultzer]

@sensiblearts We are using :libcluster, Honeydew and Pow in production with :mnesia for queue and session cache. We don't have any issues.

[sensiblearts]

@Schultzer Cool, thank you.

You guys related?

[danschultzer]

@sensiblearts Having both Pow and a queue system running on Mnesia is no issue, but if you need distribution for both then I would probably separate the two into individual local Mnesia nodes rather than running both in the same node. Try start the Pow MnesiaCache before Que.

Also it may be better to centralize the job queue (postgres/redis/mnesia) since job queue processing should be handled by node(s) separated from the web endpoints. Not sure if distributed job queue makes sense here.

I don't believe that Mnesia is related to this issue. There is something that halts email delivery for whatever reason. I've been helping a user on the elixir slack channel pretty much the same issue, email confirmation is the only email not working and it only happens in production. In their case they couldn't even get Logger to print debug messages after a certain point (e.g. Logger doesn't output message when added to process/1 or when added to certain spots inside Pow code).

It's beyond me how this can happen. I feel I'm missing something obvious but without reproducible codebase I can't figure it out.

Edit:

You guys related?

Yeah, that's my brother.

[sensiblearts]

@danschultzer Thanks, that manual code I mentioned that was starting Que after Pow. And you're right, I don't need really need a distributed queue. (You mentioned it, and I thought this through before but did't write it down. I can't work at your speed; I'm 59 years old.)

@albertoramires , please ignore my comment about mnesia in your case.

Anyway, I'll create a fresh project and try to replicate the problem, and let you know.

Thought: Could a transient process be shutting down faster in production, and not have time to finish the callback? Or maybe DNS redirects in production (www.my vs. my) load new controllers and kill something? Speculating.

[sensiblearts]

I made a simple project without any mailer (just log to debug).

It does work for:
mix phx.server and MIX_ENV=prod mix phx.server

but it does not work for:

MIX_ENV=prod mix release beta1
_build/prod/rel/powprod/bin/beta1 start

behavior: It just hangs, no output at all, no log file created. Won't boot.

(Note that I named the release inside mix.exs. I tried the default, too; same beahvior.)

I'll try again tomorrow.

[Schultzer]

@sensiblearts Can you please share the project?

[sensiblearts]

@danschultzer , @Schultzer , @albertoramires : The simple project (above) was not working because of that silly config server: true -- which I've forgotten twice now.

Results: The bug does not occur in a simple project. @Schultzer , no point in sending that project, since it works.

Below, "success" means that an IO.puts to the log file shows that the process/1 callback is being called in the Mailer.

In a FRESH PROJECT with a dummy (log only) Mailer:

mix phx.server
"success"

MIX_ENV=prod mix phx.server
"success"

_build/prod/rel/beta1/bin/beta1 start
"success"

Now, switch to my REAL PRODUCTION APP (running localhost):

tldr: All "success", too; hence, my next step is to diff the current state of my production app and try to narrow it down. I'll share another update Monday.

Details of what I did with my production app:

1) replace mailer with one that only logs
2) remove Swoosh from mix.exs
3) leave Que in mix.exs {:que, "~> 0.10.1", runtime: false } but don't start it in application
Then:

mix phx.server
"success"

MIX_ENV=prod mix phx.server
"success"

_build/prod/rel/beta1/bin/beta1 start
"success"

4) add Swoosh back to mix.exs, and add it to :extra_applications

_build/prod/rel/beta1/bin/beta1 start
"success"

5) bring back the original mailer that uses Swoosh/sAmazonSES

_build/prod/rel/beta1/bin/beta1 start
"success" and actual email received from AmazonSES

6) start Que again (manually, in application.ex)

_build/prod/rel/beta1/bin/beta1 start
"success" and actual email received from AmazonSES

7) let the app start Que (remove manual code, and in mix, remove runtime: false)

_build/prod/rel/beta1/bin/beta1 start
"success" and actual email received from AmazonSES

So, although I still have issues with Que, it's apparently not contributing to this problem, as @danschultzer said.

Again, my next step is to diff the current state of my production app and try to narrow it down.

If I can get the bug to reproduce in a localhost prod release, then I will have found the problem.

If I cannot then I will push it out to DigitalOcean and see if it happens live.

More later.

[sensiblearts]

Update: It seems to be an environment issue.

All of the following refer to a mix release build of my actual app running in MIX_ENV=prod mode.

"Success" means that actual emails were sent and delivered, for both Registration, and for attempt to sign in with email unconfirmed. Results:

1) Run on localhost, connected to local DEV database, and behind HAProxy and (self signed) SSL cert:

"success"

2) As in (1) but connected remotely to production database on DigitalOcean:

"success"

3) Exact same binaries as in (2), pushed out to DigitalOcean:

"failure"

As we found in the beginning:

A production release running on DigitalOcean (domain GardenJournal.App), with Pow v1.0.13 behaves as follows:

def deliver(conn, email) do
    config = Plug.fetch_config(conn)
    mailer = Config.get(config, :mailer_backend) || raise_no_mailer_backend_set()

    email
    |> mailer.cast()  # succeeds
    |> mailer.process() # "fails to reach callback target
  end

However, the exact same binaries running in a localhost environment, behind HAProxy and self signed SSL, and connected to remote (DigitalOcean) database, succeeds at both cast/1 and process/1.

[sensiblearts]

@danschultzer , @Schultzer , I made some progress: Test project works.

I added to the new phoenix app so that it is only:

     {:pow, "~> 1.0.13"},
      {:swoosh, "~> 0.23"},
      {:gen_smtp, "~> 0.13"},
      {:ex_aws, "~> 2.1"}

Also, it connects to my production database and uses my SES keys.

I pushed this out on an Ubuntu server identical to the one that is failing, but this one succeeds! to send email confirmations.

So @danschultzer and @Schultzer can forget about it for now -- it does not appear to be Pow problem.

As for @albertoramires , I will go through the projects and see what differences I can find on Tuesday.

Actually I may test the firewall idea today.

[sensiblearts]

@danschultzer , @Schultzer , @albertoramires , what do you make of this?:

Again, I'm testing whether a message in log file shows that process/1 is being called, and if the email is actually sent.

If I direct my browser to:

• gardenjournal.app, then it is broken; process/1 is not called

• the IP for the HAProxy load balancer, then it is _partly_ broken: process/1 is called because I see the debug message in the log. However, the email is not sent after a new registration is created.

• the IP for the backend webserver, then it works fine; email arrives.

So, it seems like, the more layers it has to go through (DNS, proxy, phoenix routing), the longer it takes, then the less of the sequence gets completed.

Again, to me this looks like a process dies early or otherwise cannot complete. Speculation: Is the session process supervising the Mailer, and when an unconfirmed email is detected (or registration attempted), could the old session be discarded as a new one is created?

[danschultzer]

Oh, that's curious. I wonder, is the e-mail delivery async? I have no idea what actually happens here. If you get redirected with warning message then the whole chain is definitely called, with the e-mail being sent, but I wonder if the mailer (and logger) are async processes that gets terminated before they are done.

Again, to me this looks like a process dies early or otherwise cannot complete. Speculation: Is the session process supervising the Mailer, and when an unconfirmed email is detected (or registration attempted), could the old session be discarded as a new one is created?

The mailer is separate from the session.

[jmn]

I just tried on my server to log in an unconfirmed user via http://localhost:4000 (lynx, directly on the server) and the confirmation email was sent. However, if I access it via my Nginx fronted domain the email never gets sent, that is process() doesn't get called.

[jmn]

I tried using Caddy v2 as the reverse proxy instead of Nginx and the email was sent.

[Abat]

So, it seems like, the more layers it has to go through (DNS, proxy, phoenix routing), the longer it takes, then the less of the sequence gets completed.

Again, to me this looks like a process dies early or otherwise cannot complete. Speculation: Is the session process supervising the Mailer, and when an unconfirmed email is detected (or registration attempted), could the old session be discarded as a new one is created?

I have the same issue in production (nginx). When I create a user, I get 'email is sent' success flash.
No email is really sent though.

Then, I tried to sign in as the same user. Since email is unconfirmed, it warns me that I need to confirm email first.

I repeat this process of signing-in about 3 times and each time I get a little bit further in my "IO.inspect" debug logs. So to me it also looks like for some reason confirmation process dies early. But since each time it goes slightly further, it seems that something is giving it more time on each subsequent try. Up to 3 times or so.

[sensiblearts]

@danschultzer , Looking at the code again today. I misspoke in earlier posts; I said "session" when I meant connection. Also, when I "log" debug info I meant just IO.puts:

  def process(email) do
    IO.puts "==DELIVERING EMAIL=="  # sometimes see, sometimes not
    deliver(email) # sometimes receive email, sometimes not
  end

I don't know about the internals of IO.puts, but it seems like not seeing that output would be a Pow issue.

And as the @Abat says above, it seems to get further into the function call if there are fewer layers/obstacles, i.e., if it's faster.

[sensiblearts]

Looking through PowEmailConfirmation.Phoenix.ControllerCallbacks, I have no ideas.

Speculating: is it possible that PowEmailConfirmation.Plug.maybe_renew_conn is broken and renewing the connection when it should not?

@danschultzer : Do you think it's worth my time to fork Pow and step through, try to find a Pow issue? Or do you still think it's with the mailers?
Thanks.

[Abat]

def create(params) do
    Multi.new
    |> Multi.run(:user, fn Platform.Repo, _ ->
      IO.inspect "1"
      pow_create(params)
    end)
    |> Multi.run(:profile, fn _repo, %{user: user} ->
        IO.inspect "2"
        PlatformWeb.Email.welcome_email |> PlatformWeb.PowMailer.deliver_now
        Platform.Profiles.create_profile(user.id)
    end)
    |> Repo.transaction
    |> case do
      {:ok, %{user: user, profile: profile}} ->
        # Yay, success!
        IO.inspect "3"
        {:ok, user}
      {:error, op, res, others} ->
        {:error, res}
    end
  end

In my Users context, I tested sending an email as can be seen above. With nginx and in fully production mode. It works.

This seems to prove to me that the issue is with Pow's EmailConfirmation. Sorry if the assumption is incorrect and I missed something.

Really want to figure it out!

[Abat]

in defmodule PowEmailConfirmation.Phoenix.ControllerCallbacks do

in defp halt_and_send_confirmation_email(conn, return_path) do

If I comment out Phoenix.Controller.redirect(to: return_path) in

conn =
conn
|> Phoenix.Controller.put_flash(:error, error)
# |> Phoenix.Controller.redirect(to: return_path)

Email is sent! Could someone please have a look if I'm on to something?

[danschultzer]

@Abat I think you're onto something! That's one of the changes in v1.0.13.

send_confirmation_email/2 is called after Phoenix.Controller.redirect/2. Redirect uses Plug.Conn.send_resp/1 which may cause email delivery to be blocked.

Try change the order:

   defp halt_and_send_confirmation_email(conn, return_path) do
     user        = Plug.current_user(conn)
     {:ok, conn} = Plug.clear_authenticated_user(conn)
     error       = extension_messages(conn).email_confirmation_required(conn)
-    conn        =
+
+    send_confirmation_email(user, conn)
+
+    conn =
       conn
       |> Phoenix.Controller.put_flash(:error, error)
       |> Phoenix.Controller.redirect(to: return_path)

-    send_confirmation_email(user, conn)
-
     {:halt, conn}
   end

I'll update the master branch to call redirect last.

[Abat]

@Abat I think you're onto something! That's one of the changes in v1.0.13.

send_confirmation_email/2 is called after Phoenix.Controller.redirect/2. Redirect uses Plug.Conn.send_resp/1 which may cause email delivery to be blocked.

Try change the order:

   defp halt_and_send_confirmation_email(conn, return_path) do
     user        = Plug.current_user(conn)
     {:ok, conn} = Plug.clear_authenticated_user(conn)
     error       = extension_messages(conn).email_confirmation_required(conn)
-    conn        =
+
+    send_confirmation_email(user, conn)
+
+    conn =
       conn
       |> Phoenix.Controller.put_flash(:error, error)
       |> Phoenix.Controller.redirect(to: return_path)

-    send_confirmation_email(user, conn)
-
     {:halt, conn}
   end

I'll update the master branch to call redirect last.

I did just that :) Was about to post. Thanks a lot guys! Thanks for Pow!

[danschultzer]

Opened #309. Be warned that the current master has a lot of refactoring that could break your cache store if you downgrade after so I recommend first testing this out by just updating Pow locally with the above fix to confirm it works. I plan to release v1.0.14 this week.

@sensiblearts @jmn can you confirm?

[sensiblearts]

@danschultzer , Yes! that fixed it for me. Beers for @Abat and @danschultzer .

[jmn]

Confirmed working. Well done guys!