Closed kudojp closed 4 years ago
kudojp
commented
4 years ago Started GET "/my_test/env_var" for ::1 at 2020-08-29 17:01:14 +0900
(0.6ms) SELECT sqlite_version(*)
Processing by MyTestController#env_var as HTML
Completed 200 OK in 1ms (Views: 0.2ms | ActiveRecord: 0.0ms | Allocations: 204)これのやり方に従ってやる
From: /Users/daiki-kudo/repos2/test_app/app/controllers/my_test_controller.rb:6 :
1: # frozen_string_literal: true
2:
3: class MyTestController < ApplicationController
4: before_action do
5: require 'pry'; binding.pry
=> 6: end
7:
8: def env_var
9: render json: { should_show_in_app_purchase: ENV['ENABLE_APPLE_IAP'].to_d }
10: end
11: end
[1] pry(#<MyTestController>)> _process_action_callbacks
=> #<ActiveSupport::Callbacks::CallbackChain:0x00007fd4a7c72800
@callbacks=
#<ActiveSupport::Callbacks::CallbackSequence:0x00007fd4ad927ac8
@after=[],
@before=[#<Proc:0x00007fd4ad927820 /Users/daiki-kudo/.rbenv/versions/2.7.0/lib/ruby/gems/2.7.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:194>],
@call_template=nil,
@nested=nil,
@user_conditions=nil>,
@chain=
[#<ActiveSupport::Callbacks::Callback:0x00007fd4a7c72918
@chain_config={:scope=>[:kind], :terminator=>#<Proc:0x00007fd4a59e9b58 /Users/daiki-kudo/.rbenv/versions/2.7.0/lib/ruby/gems/2.7.0/gems/actionpack-6.0.3.2/lib/abstract_controller/callbacks.rb:34 (lambda)>, :skip_after_callbacks_if_terminated=>true},
@filter=#<Proc:0x00007fd4a7c72a08 /Users/daiki-kudo/repos2/test_app/app/controllers/my_test_controller.rb:4>,
@if=[],
@key=20240,
@kind=:before,
@name=:process_action,
@unless=[]>],
@config={:scope=>[:kind], :terminator=>#<Proc:0x00007fd4a59e9b58 /Users/daiki-kudo/.rbenv/versions/2.7.0/lib/ruby/gems/2.7.0/gems/actionpack-6.0.3.2/lib/abstract_controller/callbacks.rb:34 (lambda)>, :skip_after_callbacks_if_terminated=>true},
@mutex=#<Thread::Mutex:0x00007fd4a7c727b0>,
@name=:process_action>kudojp/change-log-levelブランチにbinding.pryを含むコードをpushして以下を走らせたが、binding concolseで実行を試せるわけでもない。
kube sandbox fork remote -n wantedly kudojp/change-sandbox-log-level -e SAME_SATE_NONE=false -s wantedly-nodeport
kudojp
commented
4 years ago ローカル環境で、release_flagを叩いた時のログ。PGのコネクションに失敗している。
kudojp
commented
4 years ago .envから、DATABASE_URL=postgres://high1class2neet3:yFFaaM3enCcgnhBDEO1J@private-dev-db.wantedly.com:5432/natsubatecat789この一行を消してみる。
その前にDATABASE_URLは定義されているから
kudojp
commented
4 years ago app/controllers/base_controller.rbにて、 before_action do
require 'pry'; binding.pry
end[19] pry(#<Api::V2::AppleInAppPurchaseController>)> _process_action_callbacks.send(:chain).count()
=> 18
_process_action_callbacks.send(:chain).map(&:filter)
=> [:set_controller_action,
:init_i18n_debugger,
70257173622540,
70257173687760,
:clean_temp_files,
:deinit_i18n_debugger,
:ignore_newrelic,
:log_to_td,
70257079167540,
:set_current_user,
:restrict_access,
:set_locale,
:reset_timezone,
:set_timezone,
:always_save_accessed_at,
:set_start_response_time,
:log_client_error,
:prepare_restful_params]どうやらRails6ではこの記事の頃のように、全てのactionをスキップするすべはなさそうであり、
ここにあるように、skip_*_actionを一つずつ設定しなければいけないようだ。BaseControllerで、
skip_before_action *_process_action_callbacks.map(&:filter)ではダメなので、
--- a/app/controllers/base_controller.rb
+++ b/app/controllers/base_controller.rb
@@ -11,8 +11,8 @@ class BaseController < ActionController::Base
prepend_around_action :set_controller_action
- before_action :ignore_newrelic, if: -> { !Rails.env.test? && !Rails.env.development? && warmup_request? }
- after_action :log_to_td # use after_action to avoid logging redirection
+ # before_action :ignore_newrelic, if: -> { !Rails.env.test? && !Rails.env.development? && warmup_request? }
+ # after_action :log_to_td # use after_action to avoid logging redirection--- a/app/controllers/concerns/api/base_controller_concern.rb
+++ b/app/controllers/concerns/api/base_controller_concern.rb
@@ -6,14 +6,16 @@ module Api::BaseControllerConcern
include AuthenticationTokenControllerConcern
include AppConditionHelper
- before_action :set_current_user
- before_action :restrict_access
- before_action :set_locale
- around_action :reset_timezone
- before_action :set_timezone
- before_action :always_save_accessed_at
- before_action :set_start_response_time
- after_action :log_client_error, if: -> { response.client_error? }
+ # before_action :set_current_user
+ # before_action :restrict_access
+ # skip_before_action :set_current_user
+ # skip_before_action :restrict_access
+ # before_action :set_locale
+ # around_action :reset_timezone
+ # before_action :set_timezone
+ # before_action :always_save_accessed_at
+ # before_action :set_start_response_time
+ # after_action :log_client_error, if: -> { response.client_error? }
respond_to :json
endこの結果、
Started GET "/api/v2/apple_in_app_purchase/release_flag" for ::1 at 2020-08-30 20:53:48 +0900
Processing by Api::V2::AppleInAppPurchaseController#release_flag as JSON
[active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.07ms)
Completed 200 OK in 3ms (Views: 0.5ms | Allocations: 2076)なお、この時に呼び出されるfilterは
[15] pry(#<Api::V2::AppleInAppPurchaseController>)> _process_action_callbacks.send(:chain).map{|c|puts "#{c.kind} - #{c.filter}"}
around - set_controller_action
before - init_i18n_debugger
before - 70342373038800
before - 70342369270780
after - clean_temp_files
after - deinit_i18n_debugger
before - 70342322033860
before - prepare_restful_paramsこれにしたがって、
class ApplicationController < ActionController::Base
around_action :collect_metrics
def collect_metrics
start = Time.now
yield
duration = Time.now - start
Rails.logger.info "#{controller_name}##{action_name}: #{duration}s"
end
end
``
なお、この時に通っているfilterに関しては、
これでもいけそういくつかコメントアウトを外して、filterを増やしてみる。
--- a/app/controllers/base_controller.rb
+++ b/app/controllers/base_controller.rb
@@ -12,7 +12,11 @@ class BaseController < ActionController::Base
prepend_around_action :set_controller_action
before_action :ignore_newrelic, if: -> { !Rails.env.test? && !Rails.env.development? && warmup_request? } ///////////増えた
- after_action :log_to_td # use after_action to avoid logging redirection
+ # after_action :log_to_td # use after_action to avoid logging redirection--- a/app/controllers/concerns/api/base_controller_concern.rb
+++ b/app/controllers/concerns/api/base_controller_concern.rb
@@ -6,12 +6,12 @@ module Api::BaseControllerConcern
include AuthenticationTokenControllerConcern
include AppConditionHelper
- before_action :set_current_user
- before_action :restrict_access
- before_action :set_locale
- around_action :reset_timezone
- before_action :set_timezone
- before_action :always_save_accessed_at
+ # before_action :set_current_user
+ # before_action :restrict_access
+ # before_action :set_locale
+ # around_action :reset_timezone
+ # before_action :set_timezone
+ # before_action :always_save_accessed_at
before_action :set_start_response_time ///////////増えた
after_action :log_client_error, if: -> { response.client_error? } ///////////増えた
respond_to :jsonこの時のレスポンスは
Started GET "/api/v2/apple_in_app_purchase/release_flag" for ::1 at 2020-08-30 21:24:09 +0900
Processing by Api::V2::AppleInAppPurchaseController#release_flag as JSON
[active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.07ms)
Completed 200 OK in 3ms (Views: 0.4ms | Allocations: 2137)つまり、以下は無害ということ。
[1] pry(#<Api::V2::AppleInAppPurchaseController>)> _process_action_callbacks.send(:chain).map{|c|puts "#{c.kind} - #{c.filter}"}
around - set_controller_action
before - init_i18n_debugger
before - 70342373038800
before - 70342369270780
after - clean_temp_files
after - deinit_i18n_debugger
before - ignore_newrelic
before - 70342272086960
before - set_start_response_time
after - log_client_error
before - prepare_restful_params# Api::BaseControllerConcern
- after_action :log_to_td # use after_action to avoid logging redirection
# module Api::BaseControllerConcern
- before_action :set_current_user
- before_action :restrict_access
- before_action :set_locale
- around_action :reset_timezone
- before_action :set_timezone
- before_action :always_save_accessed_at
kudojp
commented
4 years ago telepresenceコマンドで家からでも共用DBにつなげる
kudojp
commented
4 years ago class BaseController < ActionController::Base
include I18nDebuggableControllerConcern
include RequestLocalizationConcern
include LocalizedHostConcern
include Pundit
include ActorContextMappingConcern
extend OpenApiAnnotator::ControllerAnnotatable
class CannotSwitchCurrentCompanyError < StandardError; end
class CurrentCompanyMismatchError < StandardError; end
prepend_around_action :set_controller_action
before_action :ignore_newrelic, if: -> { !Rails.env.test? && !Rails.env.development? && warmup_request? }
after_action :log_to_td # use after_action to avoid logging redirection
before_action do
suspected_filters = %i[log_to_td set_current_user restrict_access set_locale reset_timezone set_timezone always_save_accessed_at]
for filter in suspected_filters
_process_action_callbacks.send(:chain).each{|c| puts c.filter}
orig_filter = self.method(filter)
puts self
self.define_singleton_method(filter) do
t = Time.now()
orig_filter.call()
puts("########## #{filter} #{Time.now() - t}")
end
end
endので、一つ一つのメソットにベタがきする。
kudojp
commented
4 years ago 新谷さんと話した結果、以下の方針でいく。
config/initializers/内にrubyファイルを作り、そこで既に読み込まれているControllerのクラス(インスタンスではない！)に対して黒魔術と用いることで、filterに指定されているメソッドを、その処理内でかかった時間を常時するように上書きする。
kudojp
commented
4 years ago Started GET "/api/v2/apple_in_app_purchase/release_flag" for ::1 at 2020-08-31 18:58:51 +0900
Processing by Api::V2::AppleInAppPurchaseController#release_flag as JSON
User Load (7.3ms) SELECT "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" = $2 LIMIT $3 [["deleted", false], ["id", 140223370], ["LIMIT", 1]]
Job Load (7.0ms) SELECT "jobs".* FROM "jobs" WHERE "jobs"."deleted_at" IS NULL AND "jobs"."user_id" = $1 AND "jobs"."selected" = $2 LIMIT $3 [["user_id", 140223370], ["selected", true], ["LIMIT", 1]]
Company Load (7.7ms) SELECT "companies".* FROM "companies" WHERE "companies"."deleted_at" IS NULL AND "companies"."id" = $1 LIMIT $2 [["id", 2355211], ["LIMIT", 1]]
Preference Load (8.5ms) SELECT "preferences".* FROM "preferences" WHERE "preferences"."deleted_at" IS NULL AND "preferences"."user_id" = $1 LIMIT $2 [["user_id", 140223370], ["LIMIT", 1]]
[active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.04ms)
Job Load (7.7ms) SELECT "jobs".* FROM "jobs" WHERE "jobs"."deleted_at" IS NULL AND "jobs"."user_id" = $1 AND "jobs"."company_id" = $2 LIMIT $3 [["user_id", 140223370], ["company_id", 2355211], ["LIMIT", 1]]
UserDetail Load (9.3ms) SELECT "user_details".* FROM "user_details" WHERE "user_details"."deleted_at" IS NULL AND "user_details"."id" = $1 LIMIT $2 [["id", 140223370], ["LIMIT", 1]]
Job Load (8.5ms) SELECT "jobs".* FROM "jobs" WHERE "jobs"."deleted_at" IS NULL AND "jobs"."user_id" = $1 [["user_id", 140223370]]
(7.7ms) SELECT "experimentings"."experiment_id", "experimentings"."variation" FROM "experimentings" WHERE "experimentings"."target_id" = $1 AND "experimentings"."target_type" = $2 [["target_id", 140223370], ["target_type", "User"]]
(7.6ms) SELECT "experiments"."id" FROM "experiments" WHERE "experiments"."fixed_at" IS NULL
FLUENTD_URL was not found in the environment. Please set it. Fluent Logger is disabled.
Post an event to log ({:datetime=>"2020-08-31 18:58:51 +0900", :request_id=>nil, :user=>140223370, :company=>nil, :company_name=>nil, :company_plan=>nil, :role=>3, :admin_user=>0, :session=>"a699ce18a2f1e477e2b1f47d78d18a0b", :ip=>"::1", :remote_ip=>"::1", :remote_addr=>"::1", :tracking_code=>"7515c9c95307cf91d4e5a62e771f8aaeb327e946", :locale=>"ja", :country=>"japan", :controller=>"api/v2/apple_in_app_purchase", :action=>"release_flag", :host=>"localhost", :path=>"/api/v2/apple_in_app_purchase/release_flag", :method=>"GET", :prev_controller=>nil, :prev_action=>nil, :referrer=>nil, :referrer_host=>"(not given)", :user_agent=>"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.135 Safari/537.36", :mobile=>0, :feature_phone=>0, :smart_phone=>0, :tablet=>0, :background=>0, :source_cd=>0, :utm_source=>nil, :utm_medium=>nil, :utm_campaign=>nil, :social_source=>nil, :format=>"json", :response_status=>200, :response_time=>0.107949, :is_bot=>0, :is_xhr=>nil, :experiments=>{}, :params=>"{\"experiments\":{}}", :log_uuid=>"03588885-0345-4256-8b2c-71ad1b47c8e7", :time=>"2020-08-31 09:58:52.073420"}).
Completed 200 OK in 493ms (Views: 1.1ms | ActiveRecord: 259.4ms | Allocations: 108508)
Started GET "/api/v2/apple_in_app_purchase/release_flag" for ::1 at 2020-08-31 18:58:55 +0900
Processing by Api::V2::AppleInAppPurchaseController#release_flag as JSON
User Load (7.2ms) SELECT "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" = $2 LIMIT $3 [["deleted", false], ["id", 140223370], ["LIMIT", 1]]
Job Load (6.7ms) SELECT "jobs".* FROM "jobs" WHERE "jobs"."deleted_at" IS NULL AND "jobs"."user_id" = $1 AND "jobs"."selected" = $2 LIMIT $3 [["user_id", 140223370], ["selected", true], ["LIMIT", 1]]
Company Load (6.7ms) SELECT "companies".* FROM "companies" WHERE "companies"."deleted_at" IS NULL AND "companies"."id" = $1 LIMIT $2 [["id", 2355211], ["LIMIT", 1]]
Preference Load (6.9ms) SELECT "preferences".* FROM "preferences" WHERE "preferences"."deleted_at" IS NULL AND "preferences"."user_id" = $1 LIMIT $2 [["user_id", 140223370], ["LIMIT", 1]]
[active_model_serializers] Rendered ActiveModel::Serializer::Null with Hash (0.04ms)
Job Load (6.5ms) SELECT "jobs".* FROM "jobs" WHERE "jobs"."deleted_at" IS NULL AND "jobs"."user_id" = $1 AND "jobs"."company_id" = $2 LIMIT $3 [["user_id", 140223370], ["company_id", 2355211], ["LIMIT", 1]]
UserDetail Load (6.7ms) SELECT "user_details".* FROM "user_details" WHERE "user_details"."deleted_at" IS NULL AND "user_details"."id" = $1 LIMIT $2 [["id", 140223370], ["LIMIT", 1]]
Job Load (6.6ms) SELECT "jobs".* FROM "jobs" WHERE "jobs"."deleted_at" IS NULL AND "jobs"."user_id" = $1 [["user_id", 140223370]]
(6.4ms) SELECT "experimentings"."experiment_id", "experimentings"."variation" FROM "experimentings" WHERE "experimentings"."target_id" = $1 AND "experimentings"."target_type" = $2 [["target_id", 140223370], ["target_type", "User"]]
(6.9ms) SELECT "experiments"."id" FROM "experiments" WHERE "experiments"."fixed_at" IS NULL
Post an event to log ({:datetime=>"2020-08-31 18:58:56 +0900", :request_id=>nil, :user=>140223370, :company=>nil, :company_name=>nil, :company_plan=>nil, :role=>3, :admin_user=>0, :session=>"a699ce18a2f1e477e2b1f47d78d18a0b", :ip=>"::1", :remote_ip=>"::1", :remote_addr=>"::1", :tracking_code=>"7515c9c95307cf91d4e5a62e771f8aaeb327e946", :locale=>"ja", :country=>"japan", :controller=>"api/v2/apple_in_app_purchase", :action=>"release_flag", :host=>"localhost", :path=>"/api/v2/apple_in_app_purchase/release_flag", :method=>"GET", :prev_controller=>nil, :prev_action=>nil, :referrer=>nil, :referrer_host=>"(not given)", :user_agent=>"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.135 Safari/537.36", :mobile=>0, :feature_phone=>0, :smart_phone=>0, :tablet=>0, :background=>0, :source_cd=>0, :utm_source=>nil, :utm_medium=>nil, :utm_campaign=>nil, :social_source=>nil, :format=>"json", :response_status=>200, :response_time=>0.023482, :is_bot=>0, :is_xhr=>nil, :experiments=>{}, :params=>"{\"experiments\":{}}", :log_uuid=>"9bd73b08-25df-4c2c-bf75-6a24c36b6b0a", :time=>"2020-08-31 09:58:56.050705"}).
Completed 200 OK in 89ms (Views: 0.4ms | ActiveRecord: 60.5ms | Allocations: 16661)
wのだと
AppleInAppPurchaseControllerが継承しているクラス/モジュール
``` [8] pry(main)> Api::V2::AppleInAppPurchaseController.ancestors => [Api::V2::AppleInAppPurchaseController, #rails newしたアプリだと
これ
``` [4] pry(main)> MyTestController.ancestors => [MyTestController, #