postgresql - 为什么设计注册#create，:trackable doing an INSERT instead of UPDATE?

Question

您好，我在运行 MRI 2.2.3 的 Rails 4.2.4 应用程序中使用 Devise 3.5.3，配置如下:

app/models/user.rb:
  devise :confirmable, :database_authenticatable, :registerable, :recoverable, :rememberable, :trackable, :validatable

这是导致问题的流程:

1. 提交带有单个属性的新注册表，:email
2. 用户的 before_validation 回调成功添加了一个必需的属性，:pid
3. 设计注册 Controller 插入必要的属性(:email、:pid、:created_at、:confirmation_token 等)
4. 设计 :confirmable 发送确认邮件
5. 设计 :trackable 收集它为先前插入的用户记录跟踪的 5 个属性

那么问题来了:

1. 设计尝试插入(而不是更新)
2. Postgres 在所需列“pid”上抛出 NotNullViolation
3. pid 之前已插入，因此更新可以避免 NotNullViolation
4. 啊!

注意事项:

1. 我正在使用 email only sign up as described in Devise wiki ，仅将电子邮件发送到 registrations#create。
2. 我也在使用 guest user strategy as described in the Devise wiki但这与这种情况无关。
3. users 表包含设计执行其操作所需的所有字段。
4. 使用 Devise、:confirmable 和 :trackable 观察其他 Rails 项目，Devise 正确地更新了记录(上面的第 6 步。)
5. 注册 Controller 、标准设计没有定制。

问题:

1. 为什么 :trackable 执行插入而不是更新？
2. 我该如何排查和修复这个坏掉的应用？

令人沮丧的是:

1. 当我第一次构建它时，我可以发誓它是有效的。 :-(
2. 我的 letter_opener-1.4.1 gem 已停止工作，原因不明。相关？

相关日志数据如下:

Started POST "/users" for ::1 at 2016-01-19 08:42:12 -0800
Processing by RegistrationsController#create as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"VINuBSmtWh2j7oVY0JgGqHB/d7Ue6YZOdnEfGjGlwU7sY0GD0dvmQ0hSBxzGGQlM4i+h5sByMVanRWo2y0mqqA==", "user"=>{"email"=>"admin@test.com"}, "commit"=>"Join"}
   (0.1ms)  BEGIN
   (0.6ms)  SELECT "users"."pid" FROM "users"
  User Load (0.4ms)  SELECT  "users".* FROM "users" WHERE "users"."confirmation_token" = $1  ORDER BY "users"."id" ASC LIMIT 1  [["confirmation_token", "f8da655cda392edf619184fac68b3d03728c3a34abfc99e3026d1727a8d2964e"]]
  SQL (0.4ms)  INSERT INTO "users" ("email", "pid", "created_at", "updated_at", "confirmation_token", "confirmation_sent_at") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id"  [["email", "admin@test.com"], ["pid", "isgt"], ["created_at", "2016-01-19 16:42:12.148537"], ["updated_at", "2016-01-19 16:42:12.148537"], ["confirmation_token", "tsK97z8Ae2jNzKxUCPyj"], ["confirmation_sent_at", "2016-01-19 16:42:12.379778"]]
  Rendered devise/mailer/confirmation_instructions.html.slim (3.8ms)

Devise::Mailer#confirmation_instructions: processed outbound mail in 222.8ms

Sent mail to admin@test.com (368.0ms)
Date: Tue, 19 Jan 2016 08:42:12 -0800
From: team@example.com
Reply-To: team@example.com
To: admin@test.com
Message-ID: <569e6764987cf_170e83ff5065e9ae4779a7@flat-top.local.mail>
Subject: Confirmation instructions
Mime-Version: 1.0
Content-Type: text/html;
 charset=UTF-8
Content-Transfer-Encoding: 7bit

<p>
  Welcome admin@test.com!
</p>
<p>
  You can confirm your account email through the link below:
</p>
<p>
  <a href="http://localhost:3000/users/confirmation?confirmation_token=tsK97z8Ae2jNzKxUCPyj">Confirm my account</a>
</p>
  User Exists (0.5ms)  SELECT  1 AS one FROM "users" WHERE (LOWER("users"."email") = LOWER('admin@test.com') AND "users"."id" != 80) LIMIT 1
   (0.3ms)  ROLLBACK
   (0.1ms)  BEGIN
  SQL (8.9ms)  INSERT INTO "users" ("last_sign_in_at", "current_sign_in_at", "last_sign_in_ip", "current_sign_in_ip", "sign_in_count") VALUES ($1, $2, $3, $4, $5) RETURNING "id"  [["last_sign_in_at", "2016-01-19 16:42:13.006971"], ["current_sign_in_at", "2016-01-19 16:42:13.006971"], ["last_sign_in_ip", "::1/128"], ["current_sign_in_ip", "::1/128"], ["sign_in_count", 1]]
PG::NotNullViolation: ERROR:  null value in column "pid" violates not-null constraint
DETAIL:  Failing row contains (81, null, null, null, null, user, , , null, null, null, 1, 2016-01-19 16:42:13.006971, 2016-01-19 16:42:13.006971, ::1, ::1, null, null, null, null, null, null, null, null, null, null, null, null).
: INSERT INTO "users" ("last_sign_in_at", "current_sign_in_at", "last_sign_in_ip", "current_sign_in_ip", "sign_in_count") VALUES ($1, $2, $3, $4, $5) RETURNING "id"
   (0.1ms)  ROLLBACK
Completed 500 Internal Server Error in 876ms (ActiveRecord: 11.7ms)

PG::NotNullViolation - ERROR:  null value in column "pid" violates not-null constraint
DETAIL:  Failing row contains (81, null, null, null, null, user, , , null, null, null, 1, 2016-01-19 16:42:13.006971, 2016-01-19 16:42:13.006971, ::1, ::1, null, null, null, null, null, null, null, null, null, null, null, null).

Answer 1

我发现有一个验证错误导致第一个 INSERT 无声地失败 所以当 :trackable 出现时，记录不在那里更新。如果我注意到没有返回任何 COMMIT 消息，我就会早点发现它。

为了帮助其他人，这里是解决验证错误后的日志条目:

Started POST "/users" for ::1 at 2016-01-19 12:17:54 -0800
  ActiveRecord::SchemaMigration Load (0.4ms)  SELECT "schema_migrations".* FROM "schema_migrations"
Processing by RegistrationsController#create as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"s7xFg67CJ85OCnkZKROPkzNRBCWw3hhJQiUW0FeHLdjSBzPP8jMvIgaCVxJFPbA59UnBOZisA8h7lntvaqtJ4w==", "user"=>{"email"=>"admin@test.com"}, "commit"=>"Join"}
   (0.2ms)  BEGIN
   (0.6ms)  SELECT "users"."pid" FROM "users"
  User Load (0.4ms)  SELECT  "users".* FROM "users" WHERE "users"."confirmation_token" = $1  ORDER BY "users"."id" ASC LIMIT 1  [["confirmation_token", "ebb817b51ee9a457f75fe58d1fd29f19fb0c64cbd65122cdbe1935e8c56e48ab"]]
  SQL (0.4ms)  INSERT INTO "users" ("email", "pid", "created_at", "updated_at", "confirmation_token", "confirmation_sent_at") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id"  [["email", "admin@test.com"], ["pid", "93412"], ["created_at", "2016-01-19 20:17:54.650641"], ["updated_at", "2016-01-19 20:17:54.650641"], ["confirmation_token", "vEPtNFijrDhw5TjFh1Qy"], ["confirmation_sent_at", "2016-01-19 20:17:54.861593"]]
  Rendered devise/mailer/confirmation_instructions.html.slim (14.5ms)

Devise::Mailer#confirmation_instructions: processed outbound mail in 301.6ms

Sent mail to admin@test.com (334.7ms)
Date: Tue, 19 Jan 2016 12:17:55 -0800
From: team@example.com
Reply-To: team@example.com
To: admin@test.com
Message-ID: <569e99f32d4b0_dcb3ff7a2548e707039@flat-top.local.mail>
Subject: Confirmation instructions
Mime-Version: 1.0
Content-Type: text/html;
 charset=UTF-8
Content-Transfer-Encoding: 7bit

<p>
  Welcome admin@test.com!
</p>
<p>
  You can confirm your account email through the link below:
</p>
<p>
  <a href="http://localhost:3000/users/confirmation?confirmation_token=vEPtNFijrDhw5TjFh1Qy">Confirm my account</a>
</p>
  User Exists (0.5ms)  SELECT  1 AS one FROM "users" WHERE (LOWER("users"."email") = LOWER('admin@test.com') AND "users"."id" != 10) LIMIT 1
   (6.4ms)  COMMIT
   (0.1ms)  BEGIN
  SQL (0.3ms)  UPDATE "users" SET "last_sign_in_at" = $1, "current_sign_in_at" = $2, "last_sign_in_ip" = $3, "current_sign_in_ip" = $4, "sign_in_count" = $5, "updated_at" = $6 WHERE "users"."id" = $7  [["last_sign_in_at", "2016-01-19 20:17:55.540280"], ["current_sign_in_at", "2016-01-19 20:17:55.540280"], ["last_sign_in_ip", "::1/128"], ["current_sign_in_ip", "::1/128"], ["sign_in_count", 1], ["updated_at", "2016-01-19 20:17:55.541519"], ["id", 10]]
   (6.0ms)  COMMIT