Sporadic failure with miq_token

[Fryguy]

  1) Logging Successful Requests logging logs additional system authentication with miq_token
     Failure/Error: log_request("System Auth", {:x_miq_token => request.headers[HttpHeaders::MIQ_TOKEN]}.merge(@miq_token_hash))
     
       #<Api::ApiController:0x00000023c654a8 @_routes=nil, @_request=#<ActionDispatch::Request:0x00000022383b60 @env={"rack.version"=>[1, 3], "rack.input"=>#<StringIO:0x000000241dc8a0>, "rack.errors"=>#<StringIO:0x000000241dc918>, "rack.multithread"=>true, "rack.multiprocess"=>true, "rack.run_once"=>false, "REQUEST_METHOD"=>"GET", "SERVER_NAME"=>"www.example.com", "SERVER_PORT"=>"80", "QUERY_STRING"=>"", "PATH_INFO"=>"/api", "rack.url_scheme"=>"http", "HTTPS"=>"off", "SCRIPT_NAME"=>"", "CONTENT_LENGTH"=>"0", "rack.test"=>true, "REMOTE_ADDR"=>"127.0.0.1", "REQUEST_URI"=>"/api", "HTTP_HOST"=>"www.example.com", "CONTENT_TYPE"=>nil, "HTTP_ACCEPT"=>"text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5", "HTTP_X_MIQ_TOKEN"=>"v2:{gPU1l4OtEoDk0L0Js50oYCllMHdS+Ix1HhRgQoCGuQPmiauS/d0byn8V+RPy1H8VbdumfziKB8pjFhah2LjEGUDupDygAT+NZMkNRUZD9t30pNKxpiWWV0U4iPKz6kUrditTA/X5qf0h7/AvlDCz810FFTI9eNBFW+tDER3Mhdw=}", "HTTP_COOKIE"=>"", "action_dispatch.parameter_filter"=>[:password, :verify, :data, :_pwd, :__protected], "action_dispatch.redirect_filter"=>[], "action_dispatch.secret_token"=>"y\xD9\xCC]\xE6\xBF\b\x86\xB0\x86\xFF\x1A%\xED\xBCk\x1Cq\x80\xD2\x81bo\xB3.-\xA8\xD8\xDB\xFB\\K", "action_dispatch.secret_key_base"=>"Mbw\xF0\x86G\xE7(\xB7\x1F\e\xBF\xC2qR\xEB\x9D\xFD\xA9\xFEyP\xE8\xE5\x15\x97\x02\x9A\xF9\xDE\xB2\x8A", "action_dispatch.show_exceptions"=>true, "action_dispatch.show_detailed_exceptions"=>false, "action_dispatch.logger"=>#<VMDBLogger:0x00000001ab5260 @progname=nil, @level=1, @default_formatter=#<Logger::Formatter:0x00000001ab5170 @datetime_format=nil>, @formatter=#<VMDBLogger::Formatter:0x00000001ab4db0 @datetime_format=nil>, @logdev=#<Logger::LogDevice:0x00000001ab50a8 @shift_size=1048576, @shift_age=0, @filename=#<Pathname:/home/travis/build/ManageIQ/manageiq/log/test.log>, @dev=#<File:/home/travis/build/ManageIQ/manageiq/log/test.log>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x00000001ab4f90>>, @write_lock=#<Thread::Mutex:0x00000001ab4d10>, @local_levels={}, @thread_hash_level_key=:"ThreadSafeLogger#14002480@level">, "action_dispatch.backtrace_cleaner"=>#<Rails::BacktraceCleaner:0x00000002951be8 @filters=[#<Proc:0x00000002951080@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:14>, #<Proc:0x00000002951058@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:15>, #<Proc:0x00000002951030@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:16>, #<Proc:0x000000029507c0@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:29>], @silencers=[], @root="/home/travis/build/ManageIQ/manageiq/">, "action_dispatch.key_generator"=>#<ActiveSupport::CachingKeyGenerator:0x000000022afd30 @key_generator=#<ActiveSupport::KeyGenerator:0x000000022afe70 @secret="Mbw\xF0\x86G\xE7(\xB7\x1F\e\xBF\xC2qR\xEB\x9D\xFD\xA9\xFEyP\xE8\xE5\x15\x97\x02\x9A\xF9\xDE\xB2\x8A", @iterations=1000>, @cache_keys=#<Concurrent::Map:0x000000022afce0 entries=1 default_proc=nil>>, "action_dispatch.http_auth_salt"=>"http authentication", "action_dispatch.signed_cookie_salt"=>"signed cookie", "action_dispatch.encrypted_cookie_salt"=>"encrypted cookie", "action_dispatch.encrypted_signed_cookie_salt"=>"signed encrypted cookie", "action_dispatch.cookies_serializer"=>nil, "action_dispatch.cookies_digest"=>nil, "action_dispatch.routes"=>#<ActionDispatch::Routing::RouteSet:0x000000020b46e8>, "ROUTES_17146740_SCRIPT_NAME"=>"", "ORIGINAL_FULLPATH"=>"/api", "ORIGINAL_SCRIPT_NAME"=>"", "action_dispatch.request_id"=>"788a42e3-1707-4dbc-9e2e-78fb943aa3f2", "action_dispatch.remote_ip"=>#<ActionDispatch::RemoteIp::GetIp:0x00000022383d68 @req=#<ActionDispatch::Request:0x00000022383d90 @env={...}, @filtered_parameters=nil, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method=nil, @remote_ip=nil, @original_fullpath=nil, @fullpath=nil, @ip=nil>, @check_ip=true, @proxies=[#<IPAddr: IPv4:127.0.0.1/255.255.255.255>, #<IPAddr: IPv6:0000:0000:0000:0000:0000:0000:0000:0001/ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff>, #<IPAddr: IPv6:fc00:0000:0000:0000:0000:0000:0000:0000/fe00:0000:0000:0000:0000:0000:0000:0000>, #<IPAddr: IPv4:10.0.0.0/255.0.0.0>, #<IPAddr: IPv4:172.16.0.0/255.240.0.0>, #<IPAddr: IPv4:192.168.0.0/255.255.0.0>]>, "rack.session"=>#<ActionDispatch::Request::Session:0x22383c50 not yet loaded>, "rack.session.options"=>#<ActionDispatch::Request::Session::Options:0x00000022383c00 @by=#<ActionDispatch::Session::MemoryStore:0x00000002378410 @app=#<Rack::Head:0x000000023784b0 @app=#<Rack::ConditionalGet:0x00000002378500 @app=#<Rack::ETag:0x00000002378550 @app=#<SecureHeaders::Middleware:0x000000023785a0 @app=#<ActionDispatch::Routing::RouteSet:0x000000020b46e8>>, @cache_control="max-age=0, private, must-revalidate", @no_cache_control="no-cache">>>, @default_options={:path=>"/", :domain=>nil, :expire_after=>nil, :secure=>false, :httponly=>true, :defer=>false, :renew=>false}, @key="_session_id", @cookie_only=true>, @delegate={:path=>"/", :domain=>nil, :expire_after=>nil, :secure=>false, :httponly=>true, :defer=>false, :renew=>false}>, "action_dispatch.request.path_parameters"=>{:format=>"json", :controller=>"api/api", :action=>"index"}, "action_controller.instance"=>#<Api::ApiController:0x00000023c654a8 ...>, "action_dispatch.request.content_type"=>nil, "action_dispatch.request.request_parameters"=>{}, "rack.request.query_string"=>"", "rack.request.query_hash"=>{}, "action_dispatch.request.query_parameters"=>{}, "action_dispatch.request.parameters"=>{"format"=>"json", "controller"=>"api/api", "action"=>"index"}, "action_dispatch.request.formats"=>[#<Mime::Type:0x000000028c8578 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=335444587246358413>]}, @filtered_parameters={"format"=>"json", "controller"=>"api/api", "action"=>"index"}, @filtered_env=nil, @filtered_path=nil, @protocol="http://", @port=80, @method=nil, @request_method="GET", @remote_ip=nil, @original_fullpath="/api", @fullpath="/api", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x00000023c64418 @req=#<ActionDispatch::Request:0x00000022383b60 ...>>>, @_response=#<ActionDispatch::Response:0x00000023c65728 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x00000023c65688>, @header={}, @stream=#<ActionDispatch::Response::Buffer:0x00000023c65638 @response=#<ActionDispatch::Response:0x00000023c65728 ...>, @buf=[], @closed=false, @str_body=nil>, @status=200, @cv=#<MonitorMixin::ConditionVariable:0x00000023c65610 @monitor=#<ActionDispatch::Response:0x00000023c65728 ...>, @cond=#<Thread::ConditionVariable:0x00000023c655e8>>, @committed=false, @sending=false, @sent=false, @cache_control={}, @request=#<ActionDispatch::Request:0x00000022383b60 @env={"rack.version"=>[1, 3], "rack.input"=>#<StringIO:0x000000241dc8a0>, "rack.errors"=>#<StringIO:0x000000241dc918>, "rack.multithread"=>true, "rack.multiprocess"=>true, "rack.run_once"=>false, "REQUEST_METHOD"=>"GET", "SERVER_NAME"=>"www.example.com", "SERVER_PORT"=>"80", "QUERY_STRING"=>"", "PATH_INFO"=>"/api", "rack.url_scheme"=>"http", "HTTPS"=>"off", "SCRIPT_NAME"=>"", "CONTENT_LENGTH"=>"0", "rack.test"=>true, "REMOTE_ADDR"=>"127.0.0.1", "REQUEST_URI"=>"/api", "HTTP_HOST"=>"www.example.com", "CONTENT_TYPE"=>nil, "HTTP_ACCEPT"=>"text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5", "HTTP_X_MIQ_TOKEN"=>"v2:{gPU1l4OtEoDk0L0Js50oYCllMHdS+Ix1HhRgQoCGuQPmiauS/d0byn8V+RPy1H8VbdumfziKB8pjFhah2LjEGUDupDygAT+NZMkNRUZD9t30pNKxpiWWV0U4iPKz6kUrditTA/X5qf0h7/AvlDCz810FFTI9eNBFW+tDER3Mhdw=}", "HTTP_COOKIE"=>"", "action_dispatch.parameter_filter"=>[:password, :verify, :data, :_pwd, :__protected], "action_dispatch.redirect_filter"=>[], "action_dispatch.secret_token"=>"y\xD9\xCC]\xE6\xBF\b\x86\xB0\x86\xFF\x1A%\xED\xBCk\x1Cq\x80\xD2\x81bo\xB3.-\xA8\xD8\xDB\xFB\\K", "action_dispatch.secret_key_base"=>"Mbw\xF0\x86G\xE7(\xB7\x1F\e\xBF\xC2qR\xEB\x9D\xFD\xA9\xFEyP\xE8\xE5\x15\x97\x02\x9A\xF9\xDE\xB2\x8A", "action_dispatch.show_exceptions"=>true, "action_dispatch.show_detailed_exceptions"=>false, "action_dispatch.logger"=>#<VMDBLogger:0x00000001ab5260 @progname=nil, @level=1, @default_formatter=#<Logger::Formatter:0x00000001ab5170 @datetime_format=nil>, @formatter=#<VMDBLogger::Formatter:0x00000001ab4db0 @datetime_format=nil>, @logdev=#<Logger::LogDevice:0x00000001ab50a8 @shift_size=1048576, @shift_age=0, @filename=#<Pathname:/home/travis/build/ManageIQ/manageiq/log/test.log>, @dev=#<File:/home/travis/build/ManageIQ/manageiq/log/test.log>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x00000001ab4f90>>, @write_lock=#<Thread::Mutex:0x00000001ab4d10>, @local_levels={}, @thread_hash_level_key=:"ThreadSafeLogger#14002480@level">, "action_dispatch.backtrace_cleaner"=>#<Rails::BacktraceCleaner:0x00000002951be8 @filters=[#<Proc:0x00000002951080@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:14>, #<Proc:0x00000002951058@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:15>, #<Proc:0x00000002951030@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:16>, #<Proc:0x000000029507c0@/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/gems/railties-5.0.3/lib/rails/backtrace_cleaner.rb:29>], @silencers=[], @root="/home/travis/build/ManageIQ/manageiq/">, "action_dispatch.key_generator"=>#<ActiveSupport::CachingKeyGenerator:0x000000022afd30 @key_generator=#<ActiveSupport::KeyGenerator:0x000000022afe70 @secret="Mbw\xF0\x86G\xE7(\xB7\x1F\e\xBF\xC2qR\xEB\x9D\xFD\xA9\xFEyP\xE8\xE5\x15\x97\x02\x9A\xF9\xDE\xB2\x8A", @iterations=1000>, @cache_keys=#<Concurrent::Map:0x000000022afce0 entries=1 default_proc=nil>>, "action_dispatch.http_auth_salt"=>"http authentication", "action_dispatch.signed_cookie_salt"=>"signed cookie", "action_dispatch.encrypted_cookie_salt"=>"encrypted cookie", "action_dispatch.encrypted_signed_cookie_salt"=>"signed encrypted cookie", "action_dispatch.cookies_serializer"=>nil, "action_dispatch.cookies_digest"=>nil, "action_dispatch.routes"=>#<ActionDispatch::Routing::RouteSet:0x000000020b46e8>, "ROUTES_17146740_SCRIPT_NAME"=>"", "ORIGINAL_FULLPATH"=>"/api", "ORIGINAL_SCRIPT_NAME"=>"", "action_dispatch.request_id"=>"788a42e3-1707-4dbc-9e2e-78fb943aa3f2", "action_dispatch.remote_ip"=>#<ActionDispatch::RemoteIp::GetIp:0x00000022383d68 @req=#<ActionDispatch::Request:0x00000022383d90 @env={...}, @filtered_parameters=nil, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method=nil, @remote_ip=nil, @original_fullpath=nil, @fullpath=nil, @ip=nil>, @check_ip=true, @proxies=[#<IPAddr: IPv4:127.0.0.1/255.255.255.255>, #<IPAddr: IPv6:0000:0000:0000:0000:0000:0000:0000:0001/ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff>, #<IPAddr: IPv6:fc00:0000:0000:0000:0000:0000:0000:0000/fe00:0000:0000:0000:0000:0000:0000:0000>, #<IPAddr: IPv4:10.0.0.0/255.0.0.0>, #<IPAddr: IPv4:172.16.0.0/255.240.0.0>, #<IPAddr: IPv4:192.168.0.0/255.255.0.0>]>, "rack.session"=>#<ActionDispatch::Request::Session:0x22383c50 not yet loaded>, "rack.session.options"=>#<ActionDispatch::Request::Session::Options:0x00000022383c00 @by=#<ActionDispatch::Session::MemoryStore:0x00000002378410 @app=#<Rack::Head:0x000000023784b0 @app=#<Rack::ConditionalGet:0x00000002378500 @app=#<Rack::ETag:0x00000002378550 @app=#<SecureHeaders::Middleware:0x000000023785a0 @app=#<ActionDispatch::Routing::RouteSet:0x000000020b46e8>>, @cache_control="max-age=0, private, must-revalidate", @no_cache_control="no-cache">>>, @default_options={:path=>"/", :domain=>nil, :expire_after=>nil, :secure=>false, :httponly=>true, :defer=>false, :renew=>false}, @key="_session_id", @cookie_only=true>, @delegate={:path=>"/", :domain=>nil, :expire_after=>nil, :secure=>false, :httponly=>true, :defer=>false, :renew=>false}>, "action_dispatch.request.path_parameters"=>{:format=>"json", :controller=>"api/api", :action=>"index"}, "action_controller.instance"=>#<Api::ApiController:0x00000023c654a8 ...>, "action_dispatch.request.content_type"=>nil, "action_dispatch.request.request_parameters"=>{}, "rack.request.query_string"=>"", "rack.request.query_hash"=>{}, "action_dispatch.request.query_parameters"=>{}, "action_dispatch.request.parameters"=>{"format"=>"json", "controller"=>"api/api", "action"=>"index"}, "action_dispatch.request.formats"=>[#<Mime::Type:0x000000028c8578 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=335444587246358413>]}, @filtered_parameters={"format"=>"json", "controller"=>"api/api", "action"=>"index"}, @filtered_env=nil, @filtered_path=nil, @protocol="http://", @port=80, @method=nil, @request_method="GET", @remote_ip=nil, @original_fullpath="/api", @fullpath="/api", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x00000023c64418 @req=#<ActionDispatch::Request:0x00000022383b60 ...>>>>, @_lookup_context=#<ActionView::LookupContext:0x00000023c653e0 @details_key=nil, @cache=true, @prefixes=["api/api", "api/base"], @rendered_format=nil, @details={:locale=>[:en], :formats=>[:html, :text, :js, :css, :ics, :csv, :vcf, :png, :jpeg, :gif, :bmp, :tiff, :svg, :mpeg, :xml, :rss, :atom, :yaml, :multipart_form, :url_encoded_form, :json, :pdf, :zip, :gzip], :variants=>[], :handlers=>[:raw, :erb, :html, :builder, :ruby, :coffee, :haml, :jbuilder, :rjs]}, @view_paths=#<ActionView::PathSet:0x00000023c65228 @paths=[#<ActionView::OptimizedFileSystemResolver:0x0000000251d658 @pattern=":prefix/:action{.:locale,}{.:formats,}{+:variants,}{.:handlers,}", @cache=#<ActionView::Resolver::Cache:0x251d608 keys=0 queries=0>, @path="/home/travis/build/ManageIQ/manageiq/vendor/bundle/ruby/2.3.0/bundler/gems/manageiq-ui-classic-8b538f112477/app/views">]>>, @_action_name="index", @_response_body=nil, @requested_at=2017-06-02 18:53:56 UTC, @auth_user="api_user_id", @auth_token=nil, @user_validation_service=#<UserValidationService:0x00000023f493b8 @controller=#<Api::ApiController:0x00000023c654a8 ...>>, @miq_token_hash={:server_guid=>"987cb4f8-b071-4cb6-907a-45930e67402a", :userid=>"api_user_id", :timestamp=>2017-06-02 18:53:56 UTC}> received :log_request with unexpected arguments
         expected: ("System Auth", a hash including {:x_miq_token => "v2:{gPU1l4OtEoDk0L0Js50oYCllMHdS+Ix1HhRgQoCGuQPmiauS/d0byn8V+RPy1H...cb4f8-b071-4cb6-907a-45930e67402a", :userid => "api_user_id", :timestamp => 2017-06-02 18:53:56 UTC})
              got: ("System Auth", {:x_miq_token=>"v2:{gPU1l4OtEoDk0L0Js50oYCllMHdS+Ix1HhRgQoCGuQPmiauS/d0byn8V+RPy1H8VbdumfziKB8pjFhah2...71-4cb6-907a-45930e67402a", :userid=>"api_user_id", :timestamp=>2017-06-02 18:53:56.294714212 +0000})
       Diff:
       @@ -1,3 +1,7 @@
        ["System Auth",
       - "a hash including {:x_miq_token => \"v2:{gPU1l4OtEoDk0L0Js50oYCllMHdS+Ix1HhRgQoCGuQPmiauS/d0byn8V+RPy1H8VbdumfziKB8pjFhah2LjEGUDupDygAT+NZMkNRUZD9t30pNKxpiWWV0U4iPKz6kUrditTA/X5qf0h7/AvlDCz810FFTI9eNBFW+tDER3Mhdw=}\", :server_guid => \"987cb4f8-b071-4cb6-907a-45930e67402a\", :userid => \"api_user_id\", :timestamp => 2017-06-02 18:53:56 UTC}"]
       + {:x_miq_token=>
       +   "v2:{gPU1l4OtEoDk0L0Js50oYCllMHdS+Ix1HhRgQoCGuQPmiauS/d0byn8V+RPy1H8VbdumfziKB8pjFhah2LjEGUDupDygAT+NZMkNRUZD9t30pNKxpiWWV0U4iPKz6kUrditTA/X5qf0h7/AvlDCz810FFTI9eNBFW+tDER3Mhdw=}",
       +  :server_guid=>"987cb4f8-b071-4cb6-907a-45930e67402a",
       +  :userid=>"api_user_id",
       +  :timestamp=>2017-06-02 18:53:56.294714212 +0000}]
       
     # ./app/controllers/api/base_controller/logger.rb:17:in `log_api_auth'
     # ./app/controllers/api/base_controller/authentication.rb:30:in `require_api_user_or_token'
     # ./spec/support/api_helper.rb:14:in `run_get'
     # ./spec/requests/api/logging_spec.rb:98:in `block (3 levels) in <top (required)>'

cc @imtayadeway

Offhand it looks like the timestamp

         expected: ("System Auth", a hash including {:x_miq_token => "v2:{blah}", :userid => "api_user_id", :timestamp => 2017-06-02 18:53:56 UTC})
              got: ("System Auth", {:x_miq_token=>"v2:{blah}", :userid=>"api_user_id", :timestamp=>2017-06-02 18:53:56.294714212 +0000})

[Fryguy]

See also https://travis-ci.org/ManageIQ/manageiq/jobs/238864602

If it helps:

Randomized with seed 30045

[imtayadeway]

This might be incidentally fixed by #15058 which uses Timecop in the affected test