Bug #17437
Updated by Tom Clegg about 3 years ago
*If RailsAPI is deployed using WEBrick* -- which is the "default development web server" for rails, although it is "not a good idea to run it in production":https://devcenter.heroku.com/articles/ruby-default-web-server and it is not used in our usual test/dev setups -- *and* the arvados configuration indicates controller should connect directly to WEBrick without going through an Nginx proxy, then WEBrick does not decode controller requests properly.
See details below. tl;dr: this appears to be caused by WEBrick's improper handling of HTTP/1.1 Transfer-Encoding and Content-Length headers. The problem can be avoided by proxying requests through Nginx, which defaults to HTTP/1.0 for upstream proxy requests... or by not using WEBrick at all.
---
this is the nginx configuration
<pre>
upstream api_upstream {
# This matches the port where the api rails app is listening
# in docker-compose.yml
server api:8004 fail_timeout=10s;
}
</pre>
<pre>
server {
listen 8084;
server_name nginx-api;
client_max_body_size 128m;
location / {
proxy_pass http://api_upstream;
proxy_read_timeout 300;
proxy_connect_timeout 90;
# From https://www.phusionpassenger.com/library/deploy/standalone/reverse_proxy.html
proxy_http_version 1.1;
proxy_set_header Host $http_host;
proxy_set_header Upgrade $http_upgrade;
proxy_set_header Connection $connection_upgrade;
proxy_buffering off;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
# proxy_redirect off;
# proxy_set_header X-Forwarded-Proto https;
# proxy_set_header X-Real-IP $remote_addr;
# proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
}
}
</pre>
if we have this in arvados config:
<pre>
RailsAPI:
InternalURLs:
# WE need to pass requests through nginx, or bad things will happen
'http://nginx-api:8084': {}
</pre>
request go thru with no issue:
<pre>
# arv --format=uuid group create --group '{"owner_uuid":"z1119-tpzed-000000000000000", "group_class":"project", "name":"Arvados Standard Docker 10"}'
z1119-j7d0g-qbsbvbmen4mhdck
</pre>
This is what rails API sees:
<pre>
[req-9tfluusd20d015sgr5uf] {"CONTENT_LENGTH"=>"130", "CONTENT_TYPE"=>"application/json", "GATEWAY_INTERFACE"=>"CGI/1.1", "PATH_INFO"=>"/arvados/v1/groups", "QUERY_STRING"=>"_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "REMOTE_ADDR"=>"192.168.48.4", "REMOTE_HOST"=>"192.168.48.4", "REQUEST_METHOD"=>"POST", "REQUEST_URI"=>"https://z1119.arv.local:8000/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "SCRIPT_NAME"=>"", "SERVER_NAME"=>"z1119.arv.local", "SERVER_PORT"=>"8000", "SERVER_PROTOCOL"=>"HTTP/1.1", "SERVER_SOFTWARE"=>"WEBrick/1.6.0 (Ruby/2.7.2/2020-10-01)", "HTTP_HOST"=>"z1119.arv.local:8000", "HTTP_CONNECTION"=>"close", "HTTP_X_REAL_IP"=>"192.168.48.14", "HTTP_X_FORWARDED_FOR"=>"192.168.48.5,192.168.48.4:52266, 192.168.48.14", "HTTP_USER_AGENT"=>"arvados-cli/1.0 google-api-ruby-client/0.8.7.4 Linux/5.10.0-3-amd64 (gzip)", "HTTP_ACCEPT"=>"application/json", "HTTP_AUTHORIZATION"=>"OAuth2 v2/z1119-gj3su-rkahytczn9o7wf1/1bxebbjmt92479f7c169q5wcxgz0yewuw839fs666a3qj6wi5k", "HTTP_VIA"=>"HTTP/1.0 arvados-controller", "HTTP_X_FORWARDED_PROTO"=>"https", "HTTP_X_REQUEST_ID"=>"req-9tfluusd20d015sgr5uf", "HTTP_ACCEPT_ENCODING"=>"gzip", "rack.version"=>[1, 3], "rack.input"=>#<StringIO:0x00007f846050d908>, "rack.errors"=>#<IO:<STDERR>>, "rack.multithread"=>true, "rack.multiprocess"=>false, "rack.run_once"=>false, "rack.url_scheme"=>"http", "rack.hijack?"=>true, "rack.hijack"=>#<Proc:0x00007f846050d890 /cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/handler/webrick.rb:83 (lambda)>, "rack.hijack_io"=>nil, "HTTP_VERSION"=>"HTTP/1.1", "REQUEST_PATH"=>"/arvados/v1/groups", "action_dispatch.parameter_filter"=>[:password, :password], "action_dispatch.redirect_filter"=>[], "action_dispatch.secret_token"=>nil, "action_dispatch.secret_key_base"=>"ezx6lj8ro3f0joezenqcdn319dwsgdh8z7c7m3unwyg4y3qmg", "action_dispatch.show_exceptions"=>true, "action_dispatch.show_detailed_exceptions"=>true, "action_dispatch.logger"=>#<ActiveSupport::Logger:0x0000560ae23d1ad8 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x0000560ae23d1a10 @datetime_format=nil>, @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x0000560ae2a15908 @datetime_format=nil, @thread_key="activesupport_tagged_logging_tags:10520">, @logdev=#<Logger::LogDevice:0x0000560ae23d1970 @shift_period_suffix="%Y%m%d", @shift_size=1048576, @shift_age=0, @filename="/arvados/services/api/log/development.log", @dev=#<File:/arvados/services/api/log/development.log>, @binmode=false, @mon_data=#<Monitor:0x0000560ae23d18f8>, @mon_data_owner_object_id=8560>, @local_levels=#<Concurrent::Map:0x0000560ae23d1768 entries=0 default_proc=nil>>, "action_dispatch.backtrace_cleaner"=>#<Rails::BacktraceCleaner:0x00007f8460054f38 @filters=[#<Proc:0x00007f8460054e20 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:16>, #<Proc:0x00007f8460054df8 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:17>, #<Proc:0x00007f8460054dd0 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:18>, #<Proc:0x00007f8460054ad8 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:31>], @silencers=[#<Proc:0x00007f8460054ab0 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:21>], @root="/arvados/services/api/">, "action_dispatch.key_generator"=>#<ActiveSupport::CachingKeyGenerator:0x0000560ae421b5e8 @key_generator=#<ActiveSupport::KeyGenerator:0x0000560ae421b610 @secret="ezx6lj8ro3f0joezenqcdn319dwsgdh8z7c7m3unwyg4y3qmg", @iterations=1000>, @cache_keys=#<Concurrent::Map:0x0000560ae421b5c0 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.authenticated_encrypted_cookie_salt"=>"authenticated encrypted cookie", "action_dispatch.use_authenticated_cookie_encryption"=>false, "action_dispatch.encrypted_cookie_cipher"=>nil, "action_dispatch.signed_cookie_digest"=>nil, "action_dispatch.cookies_serializer"=>:marshal, "action_dispatch.cookies_digest"=>nil, "action_dispatch.cookies_rotations"=>#<ActiveSupport::Messages::RotationConfiguration:0x0000560ae0f69488 @signed=[], @encrypted=[]>, "action_dispatch.content_security_policy"=>nil, "action_dispatch.content_security_policy_report_only"=>false, "action_dispatch.content_security_policy_nonce_generator"=>nil, "action_dispatch.routes"=>#<ActionDispatch::Routing::RouteSet:0x0000560ae20dacf8>, "ROUTES_8360_SCRIPT_NAME"=>"", "ORIGINAL_FULLPATH"=>"/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "ORIGINAL_SCRIPT_NAME"=>"", "rack.request.query_string"=>"_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "rack.request.query_hash"=>{"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false"}, "action_dispatch.request_id"=>"req-9tfluusd20d015sgr5uf", "rack.session"=>{}, "rack.session.options"=>{:skip=>true}, "rack.tempfiles"=>[], "action_dispatch.request.path_parameters"=>{:controller=>"arvados/v1/groups", :action=>"create"}, "action_controller.instance"=>#<Arvados::V1::GroupsController:0x0000560ae3f31e90 @_action_has_layout=true, @_routes=nil, @_request=#<ActionDispatch::Request:0x00007f8460530a98 @env={...}, @filtered_parameters={"group"=>"{\"owner_uuid\":\"z1119-tpzed-000000000000000\", \"group_class\":\"project\", \"name\":\"Arvados Standard Docker 10\"}", "_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create"}, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method="POST", @remote_ip=nil, @original_fullpath=nil, @fullpath="/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x00007f846053b858 @req=#<ActionDispatch::Request:0x00007f8460530a98 ...>>>, @_response=#<ActionDispatch::Response:0x0000560ae3f32408 @mon_data=#<Monitor:0x0000560ae3f322c8>, @mon_data_owner_object_id=66900, @header={"X-Frame-Options"=>"SAMEORIGIN", "X-XSS-Protection"=>"1; mode=block", "X-Content-Type-Options"=>"nosniff", "X-Download-Options"=>"noopen", "X-Permitted-Cross-Domain-Policies"=>"none", "Referrer-Policy"=>"strict-origin-when-cross-origin", "X-Request-Id"=>"req-9tfluusd20d015sgr5uf", "Access-Control-Allow-Origin"=>"*", "Access-Control-Allow-Methods"=>"GET, HEAD, PUT, POST, DELETE", "Access-Control-Allow-Headers"=>"Authorization, Content-Type", "Access-Control-Max-Age"=>"86486400"}, @stream=#<ActionDispatch::Response::Buffer:0x0000560ae3f32228 @response=#<ActionDispatch::Response:0x0000560ae3f32408 ...>, @buf=[], @closed=false, @str_body=nil>, @status=200, @cv=#<MonitorMixin::ConditionVariable:0x0000560ae3f321b0 @monitor=#<Monitor:0x0000560ae3f322c8>, @cond=#<Thread::ConditionVariable:0x0000560ae3f32188>>, @committed=false, @sending=false, @sent=false, @cache_control={}, @request=#<ActionDispatch::Request:0x00007f8460530a98 @env={...}, @filtered_parameters={"group"=>"{\"owner_uuid\":\"z1119-tpzed-000000000000000\", \"group_class\":\"project\", \"name\":\"Arvados Standard Docker 10\"}", "_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create"}, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method="POST", @remote_ip=nil, @original_fullpath=nil, @fullpath="/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x00007f846053b858 @req=#<ActionDispatch::Request:0x00007f8460530a98 ...>>>>, @object=nil, @objects=nil, @offset=nil, @limit=nil, @select=nil, @distinct=nil, @response_resource_name=nil, @attrs={:owner_uuid=>"z1119-tpzed-000000000000000", :group_class=>"project", :name=>"Arvados Standard Docker 10"}, @extra_included=nil, @_lookup_context=#<ActionView::LookupContext:0x0000560ae3f31cb0 @details_key=nil, @cache=true, @prefixes=["arvados/v1/groups", "application"], @rendered_format=nil, @details={:locale=>[:en], :formats=>[:json], :variants=>[], :handlers=>[:raw, :erb, :html, :builder, :ruby]}, @view_paths=#<ActionView::PathSet:0x0000560ae3f31a08 @paths=[#<ActionView::OptimizedFileSystemResolver:0x0000560ae2303f70 @pattern=":prefix/:action{.:locale,}{.:formats,}{+:variants,}{.:handlers,}", @cache=#<ActionView::Resolver::Cache:0x20580 keys=0 queries=0>, @path="/arvados/services/api/app/views">]>>, @_action_name="create", @_response_body=nil, @_params=<ActionController::Parameters {"group"=>"{\"owner_uuid\":\"z1119-tpzed-000000000000000\", \"group_class\":\"project\", \"name\":\"Arvados Standard Docker 10\"}", "_profile"=>"true", "async"=>false, "cluster_id"=>"", "ensure_unique_name"=>false, "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create"} permitted: true>, @marked_for_same_origin_verification=false, @_config={}, @remote_ip="192.168.48.14", @read_auths=[#<ApiClientAuthorization id: 38, api_token: "1bxebbjmt92479f7c169q5wcxgz0yewuw839fs666a3qj6wi5k", api_client_id: 2, user_id: 3, created_by_ip_address: "192.168.48.2", last_used_by_ip_address: nil, last_used_at: nil, expires_at: nil, created_at: "2021-03-02 17:38:54", updated_at: "2021-03-02 17:38:54", default_owner_uuid: nil, scopes: ["all"], uuid: "z1119-gj3su-rkahytczn9o7wf1">], @read_users=[#<User id: 3, uuid: "z1119-tpzed-8ybit9f3z3asq79", owner_uuid: "z1119-tpzed-000000000000000", created_at: "2021-03-01 20:07:14", modified_by_client_uuid: "z1119-ozdt8-x3ld63y2ibkzt42", modified_by_user_uuid: "z1119-tpzed-000000000000000", modified_at: "2021-03-01 20:07:14", email: "alice@z1119.arv.local", first_name: "", last_name: "", identity_url: nil, is_admin: true, prefs: {}, updated_at: "2021-03-01 20:07:14", default_owner_uuid: nil, is_active: true, username: "alice", redirect_to_user_uuid: nil>]>, "action_dispatch.request.content_type"=>#<Mime::Type:0x0000560ae1b9e8c0 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=2070501007913819523>, "RAW_POST_DATA"=>"{\"group\":\"{\\\"owner_uuid\\\":\\\"z1119-tpzed-000000000000000\\\", \\\"group_class\\\":\\\"project\\\", \\\"name\\\":\\\"Arvados Standard Docker 10\\\"}\"}", "action_dispatch.request.request_parameters"=>{"group"=>"{\"owner_uuid\":\"z1119-tpzed-000000000000000\", \"group_class\":\"project\", \"name\":\"Arvados Standard Docker 10\"}"}, "action_dispatch.request.query_parameters"=>{"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false"}, "action_dispatch.request.parameters"=>{"group"=>"{\"owner_uuid\":\"z1119-tpzed-000000000000000\", \"group_class\":\"project\", \"name\":\"Arvados Standard Docker 10\"}", "_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create", "format"=>"json"}, "action_dispatch.request.accepts"=>[#<Mime::Type:0x0000560ae1b9e8c0 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=2070501007913819523>], "action_dispatch.request.formats"=>[#<Mime::Type:0x0000560ae1b9e8c0 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=2070501007913819523>], "action_dispatch.request.flash_hash"=>nil, "action_dispatch.cookies"=>#<ActionController::RequestForgeryProtection::ProtectionMethods::NullSession::NullCookieJar:0x00007f846053abb0 @set_cookies={}, @delete_cookies={}, @request=#<ActionDispatch::Request:0x00007f8460530a98 @env={...}, @filtered_parameters={"group"=>"{\"owner_uuid\":\"z1119-tpzed-000000000000000\", \"group_class\":\"project\", \"name\":\"Arvados Standard Docker 10\"}", "_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create"}, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method="POST", @remote_ip=nil, @original_fullpath=nil, @fullpath="/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x00007f846053b858 @req=#<ActionDispatch::Request:0x00007f8460530a98 ...>>>, @cookies={}, @committed=false>}
</pre>
BUT if we cahange the configuration to make it go via railsapi straight:
<pre>
RailsAPI:
InternalURLs:
'http://api:8004': {}
</pre>
then:
<pre>
arv --format=uuid group create --group '{"owner_uuid":"z1119-tpzed-000000000000000", "group_class":"project", "name":"Arvados Standard Docker 11"}'
Error: Group class value must be one of 'project' or 'role', was '' (req-1r4olxje7knuxzxetkds)
</pre>
<pre>
[req-1r4olxje7knuxzxetkds] {"CONTENT_TYPE"=>"application/json", "GATEWAY_INTERFACE"=>"CGI/1.1", "PATH_INFO"=>"/arvados/v1/groups", "QUERY_STRING"=>"_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "REMOTE_ADDR"=>"192.168.48.14", "REMOTE_HOST"=>"192.168.48.14", "REQUEST_METHOD"=>"POST", "REQUEST_URI"=>"https://z1119.arv.local:8000/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "SCRIPT_NAME"=>"", "SERVER_NAME"=>"z1119.arv.local", "SERVER_PORT"=>"8000", "SERVER_PROTOCOL"=>"HTTP/1.1", "SERVER_SOFTWARE"=>"WEBrick/1.6.0 (Ruby/2.7.2/2020-10-01)", "HTTP_HOST"=>"z1119.arv.local:8000", "HTTP_USER_AGENT"=>"arvados-cli/1.0 google-api-ruby-client/0.8.7.4 Linux/5.10.0-3-amd64 (gzip)", "HTTP_TRANSFER_ENCODING"=>"chunked", "HTTP_ACCEPT"=>"application/json", "HTTP_AUTHORIZATION"=>"OAuth2 v2/z1119-gj3su-rkahytczn9o7wf1/1bxebbjmt92479f7c169q5wcxgz0yewuw839fs666a3qj6wi5k", "HTTP_VIA"=>"HTTP/1.0 arvados-controller", "HTTP_X_FORWARDED_FOR"=>"192.168.48.5,192.168.48.4:52394", "HTTP_X_FORWARDED_PROTO"=>"https", "HTTP_X_REAL_IP"=>"192.168.48.5", "HTTP_X_REQUEST_ID"=>"req-1r4olxje7knuxzxetkds", "HTTP_ACCEPT_ENCODING"=>"gzip", "rack.version"=>[1, 3], "rack.input"=>#<StringIO:0x00007f84606c00e8>, "rack.errors"=>#<IO:<STDERR>>, "rack.multithread"=>true, "rack.multiprocess"=>false, "rack.run_once"=>false, "rack.url_scheme"=>"http", "rack.hijack?"=>true, "rack.hijack"=>#<Proc:0x00007f84606c0070 /cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/handler/webrick.rb:83 (lambda)>, "rack.hijack_io"=>nil, "HTTP_VERSION"=>"HTTP/1.1", "REQUEST_PATH"=>"/arvados/v1/groups", "action_dispatch.parameter_filter"=>[:password, :password], "action_dispatch.redirect_filter"=>[], "action_dispatch.secret_token"=>nil, "action_dispatch.secret_key_base"=>"ezx6lj8ro3f0joezenqcdn319dwsgdh8z7c7m3unwyg4y3qmg", "action_dispatch.show_exceptions"=>true, "action_dispatch.show_detailed_exceptions"=>true, "action_dispatch.logger"=>#<ActiveSupport::Logger:0x0000560ae23d1ad8 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x0000560ae23d1a10 @datetime_format=nil>, @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x0000560ae2a15908 @datetime_format=nil, @thread_key="activesupport_tagged_logging_tags:10520">, @logdev=#<Logger::LogDevice:0x0000560ae23d1970 @shift_period_suffix="%Y%m%d", @shift_size=1048576, @shift_age=0, @filename="/arvados/services/api/log/development.log", @dev=#<File:/arvados/services/api/log/development.log>, @binmode=false, @mon_data=#<Monitor:0x0000560ae23d18f8>, @mon_data_owner_object_id=8560>, @local_levels=#<Concurrent::Map:0x0000560ae23d1768 entries=0 default_proc=nil>>, "action_dispatch.backtrace_cleaner"=>#<Rails::BacktraceCleaner:0x00007f8460054f38 @filters=[#<Proc:0x00007f8460054e20 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:16>, #<Proc:0x00007f8460054df8 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:17>, #<Proc:0x00007f8460054dd0 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:18>, #<Proc:0x00007f8460054ad8 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:31>], @silencers=[#<Proc:0x00007f8460054ab0 /cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/backtrace_cleaner.rb:21>], @root="/arvados/services/api/">, "action_dispatch.key_generator"=>#<ActiveSupport::CachingKeyGenerator:0x0000560ae421b5e8 @key_generator=#<ActiveSupport::KeyGenerator:0x0000560ae421b610 @secret="ezx6lj8ro3f0joezenqcdn319dwsgdh8z7c7m3unwyg4y3qmg", @iterations=1000>, @cache_keys=#<Concurrent::Map:0x0000560ae421b5c0 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.authenticated_encrypted_cookie_salt"=>"authenticated encrypted cookie", "action_dispatch.use_authenticated_cookie_encryption"=>false, "action_dispatch.encrypted_cookie_cipher"=>nil, "action_dispatch.signed_cookie_digest"=>nil, "action_dispatch.cookies_serializer"=>:marshal, "action_dispatch.cookies_digest"=>nil, "action_dispatch.cookies_rotations"=>#<ActiveSupport::Messages::RotationConfiguration:0x0000560ae0f69488 @signed=[], @encrypted=[]>, "action_dispatch.content_security_policy"=>nil, "action_dispatch.content_security_policy_report_only"=>false, "action_dispatch.content_security_policy_nonce_generator"=>nil, "action_dispatch.routes"=>#<ActionDispatch::Routing::RouteSet:0x0000560ae20dacf8>, "ROUTES_8360_SCRIPT_NAME"=>"", "ORIGINAL_FULLPATH"=>"/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "ORIGINAL_SCRIPT_NAME"=>"", "rack.request.query_string"=>"_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", "rack.request.query_hash"=>{"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false"}, "action_dispatch.request_id"=>"req-1r4olxje7knuxzxetkds", "rack.session"=>{}, "rack.session.options"=>{:skip=>true}, "rack.tempfiles"=>[], "action_dispatch.request.path_parameters"=>{:controller=>"arvados/v1/groups", :action=>"create"}, "action_controller.instance"=>#<Arvados::V1::GroupsController:0x00007f84606ecd78 @_action_has_layout=true, @_routes=nil, @_request=#<ActionDispatch::Request:0x00007f84606ee6f0 @env={...}, @filtered_parameters={"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create", "group"=>{}}, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method="POST", @remote_ip=nil, @original_fullpath=nil, @fullpath="/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x0000560ae3b8ad28 @req=#<ActionDispatch::Request:0x00007f84606ee6f0 ...>>>, @_response=#<ActionDispatch::Response:0x00007f84606ecfa8 @mon_data=#<Monitor:0x00007f84606ecf58>, @mon_data_owner_object_id=67460, @header={"X-Frame-Options"=>"SAMEORIGIN", "X-XSS-Protection"=>"1; mode=block", "X-Content-Type-Options"=>"nosniff", "X-Download-Options"=>"noopen", "X-Permitted-Cross-Domain-Policies"=>"none", "Referrer-Policy"=>"strict-origin-when-cross-origin", "X-Request-Id"=>"req-1r4olxje7knuxzxetkds", "Access-Control-Allow-Origin"=>"*", "Access-Control-Allow-Methods"=>"GET, HEAD, PUT, POST, DELETE", "Access-Control-Allow-Headers"=>"Authorization, Content-Type", "Access-Control-Max-Age"=>"86486400"}, @stream=#<ActionDispatch::Response::Buffer:0x00007f84606ecee0 @response=#<ActionDispatch::Response:0x00007f84606ecfa8 ...>, @buf=[], @closed=false, @str_body=nil>, @status=200, @cv=#<MonitorMixin::ConditionVariable:0x00007f84606eceb8 @monitor=#<Monitor:0x00007f84606ecf58>, @cond=#<Thread::ConditionVariable:0x00007f84606ece90>>, @committed=false, @sending=false, @sent=false, @cache_control={}, @request=#<ActionDispatch::Request:0x00007f84606ee6f0 @env={...}, @filtered_parameters={"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create", "group"=>{}}, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method="POST", @remote_ip=nil, @original_fullpath=nil, @fullpath="/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x0000560ae3b8ad28 @req=#<ActionDispatch::Request:0x00007f84606ee6f0 ...>>>>, @object=nil, @objects=nil, @offset=nil, @limit=nil, @select=nil, @distinct=nil, @response_resource_name=nil, @attrs=<ActionController::Parameters {} permitted: true>, @extra_included=nil, @_lookup_context=#<ActionView::LookupContext:0x00007f84606ecc60 @details_key=nil, @cache=true, @prefixes=["arvados/v1/groups", "application"], @rendered_format=nil, @details={:locale=>[:en], :formats=>[:json], :variants=>[], :handlers=>[:raw, :erb, :html, :builder, :ruby]}, @view_paths=#<ActionView::PathSet:0x00007f84606ecb70 @paths=[#<ActionView::OptimizedFileSystemResolver:0x0000560ae2303f70 @pattern=":prefix/:action{.:locale,}{.:formats,}{+:variants,}{.:handlers,}", @cache=#<ActionView::Resolver::Cache:0x20580 keys=0 queries=0>, @path="/arvados/services/api/app/views">]>>, @_action_name="create", @_response_body=nil, @_params=<ActionController::Parameters {"_profile"=>"true", "async"=>false, "cluster_id"=>"", "ensure_unique_name"=>false, "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create", "group"=><ActionController::Parameters {} permitted: true>} permitted: true>, @marked_for_same_origin_verification=false, @_config={}, @remote_ip="192.168.48.5", @read_auths=[#<ApiClientAuthorization id: 38, api_token: "1bxebbjmt92479f7c169q5wcxgz0yewuw839fs666a3qj6wi5k", api_client_id: 2, user_id: 3, created_by_ip_address: "192.168.48.2", last_used_by_ip_address: nil, last_used_at: nil, expires_at: nil, created_at: "2021-03-02 17:38:54", updated_at: "2021-03-02 17:38:54", default_owner_uuid: nil, scopes: ["all"], uuid: "z1119-gj3su-rkahytczn9o7wf1">], @read_users=[#<User id: 3, uuid: "z1119-tpzed-8ybit9f3z3asq79", owner_uuid: "z1119-tpzed-000000000000000", created_at: "2021-03-01 20:07:14", modified_by_client_uuid: "z1119-ozdt8-x3ld63y2ibkzt42", modified_by_user_uuid: "z1119-tpzed-000000000000000", modified_at: "2021-03-01 20:07:14", email: "alice@z1119.arv.local", first_name: "", last_name: "", identity_url: nil, is_admin: true, prefs: {}, updated_at: "2021-03-01 20:07:14", default_owner_uuid: nil, is_active: true, username: "alice", redirect_to_user_uuid: nil>]>, "action_dispatch.request.content_type"=>#<Mime::Type:0x0000560ae1b9e8c0 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=2070501007913819523>, "action_dispatch.request.request_parameters"=>{"group"=>{}}, "action_dispatch.request.query_parameters"=>{"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false"}, "action_dispatch.request.parameters"=>{"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create", "group"=>{}, "format"=>"json"}, "action_dispatch.request.accepts"=>[#<Mime::Type:0x0000560ae1b9e8c0 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=2070501007913819523>], "action_dispatch.request.formats"=>[#<Mime::Type:0x0000560ae1b9e8c0 @synonyms=["text/x-json", "application/jsonrequest"], @symbol=:json, @string="application/json", @hash=2070501007913819523>], "action_dispatch.request.flash_hash"=>nil, "action_dispatch.cookies"=>#<ActionController::RequestForgeryProtection::ProtectionMethods::NullSession::NullCookieJar:0x0000560ae3b89388 @set_cookies={}, @delete_cookies={}, @request=#<ActionDispatch::Request:0x00007f84606ee6f0 @env={...}, @filtered_parameters={"_profile"=>"true", "async"=>"false", "cluster_id"=>"", "ensure_unique_name"=>"false", "group_given"=>"true", "help"=>"false", "controller"=>"arvados/v1/groups", "action"=>"create", "group"=>{}}, @filtered_env=nil, @filtered_path=nil, @protocol=nil, @port=nil, @method=nil, @request_method="POST", @remote_ip=nil, @original_fullpath=nil, @fullpath="/arvados/v1/groups?_profile=true&async=false&cluster_id=&ensure_unique_name=false&group_given=true&help=false", @ip=nil, @headers=#<ActionDispatch::Http::Headers:0x0000560ae3b8ad28 @req=#<ActionDispatch::Request:0x00007f84606ee6f0 ...>>>, @cookies={}, @committed=false>}
[req-1r4olxje7knuxzxetkds] (0.1ms) BEGIN
[req-1r4olxje7knuxzxetkds] (0.1ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[req-1r4olxje7knuxzxetkds] (0.4ms) SELECT COUNT(*) FROM "users" WHERE (redirect_to_user_uuid is null) AND (users.owner_uuid NOT IN (SELECT group_uuid FROM trashed_groups where trash_at <= statement_timestamp()) ) AND "users"."uuid" = $1 [["uuid", "z1119-tpzed-8ybit9f3z3asq79"]]
[req-1r4olxje7knuxzxetkds] (0.1ms) ROLLBACK
#<ActiveRecord::RecordInvalid: Validation failed: Group class value must be one of 'project' or 'role', was ''>
["Group class value must be one of 'project' or 'role', was ''"]
Error 1614715403+9e6228d9: 422
{"method":"POST","path":"/arvados/v1/groups","format":"json","controller":"Arvados::V1::GroupsController","action":"create","status":422,"duration":8.12,"view":0.17,"db":0.77,"request_id":"req-1r4olxje7knuxzxetkds","client_ipaddr":"192.168.48.5","client_auth":"z1119-gj3su-rkahytczn9o7wf1","exception":"#\u003cActiveRecord::RecordInvalid: Validation failed: Group class value must be one of 'project' or 'role', was ''\u003e","exception_backtrace":"/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/validations.rb:80:in `raise_validation_error'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/validations.rb:52:in `save!'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:315:in `block in save!'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `synchronize'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:212:in `transaction'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:315:in `save!'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/suppressor.rb:48:in `save!'\n/arvados/services/api/app/controllers/application_controller.rb:112:in `create'\n/arvados/services/api/app/controllers/arvados/v1/groups_controller.rb:85:in `create'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/abstract_controller/base.rb:194:in `process_action'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal/rendering.rb:30:in `process_action'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:109:in `block in run_callbacks'\n/arvados/services/api/app/controllers/application_controller.rb:431:in `block in set_current_request_id'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/tagged_logging.rb:71:in `block in tagged'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/tagged_logging.rb:28:in `tagged'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/tagged_logging.rb:71:in `tagged'\n/arvados/services/api/app/controllers/application_controller.rb:430:in `set_current_request_id'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:118:in `block in run_callbacks'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:136:in `run_callbacks'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/abstract_controller/callbacks.rb:41:in `process_action'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal/rescue.rb:22:in `process_action'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/notifications.rb:168:in `block in instrument'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/notifications.rb:168:in `instrument'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal/instrumentation.rb:32:in `process_action'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'\n/cache/gem/ruby/2.7.0/gems/activerecord-5.2.4.3/lib/active_record/railties/controller_runtime.rb:24:in `process_action'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/abstract_controller/base.rb:134:in `process'\n/cache/gem/ruby/2.7.0/gems/actionview-5.2.4.3/lib/action_view/rendering.rb:32:in `process'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal.rb:191:in `dispatch'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_controller/metal.rb:252:in `dispatch'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/routing/route_set.rb:34:in `serve'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/journey/router.rb:52:in `block in serve'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/journey/router.rb:35:in `each'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/journey/router.rb:35:in `serve'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/routing/route_set.rb:840:in `call'\n/cache/gem/ruby/2.7.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:186:in `call!'\n/cache/gem/ruby/2.7.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:164:in `call'\n/cache/gem/ruby/2.7.0/gems/omniauth-1.4.3/lib/omniauth/builder.rb:63:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/http/content_security_policy.rb:18:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/cookies.rb:670:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:98:in `run_callbacks'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/executor.rb:14:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'\n/cache/gem/ruby/2.7.0/gems/lograge-0.10.0/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'\n/cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/rack/logger.rb:26:in `block in call'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/tagged_logging.rb:71:in `block in tagged'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/tagged_logging.rb:28:in `tagged'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/tagged_logging.rb:71:in `tagged'\n/cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/rack/logger.rb:26:in `call'\n/cache/gem/ruby/2.7.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/request_id.rb:27:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'\n/cache/gem/ruby/2.7.0/gems/activesupport-5.2.4.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/executor.rb:14:in `call'\n/cache/gem/ruby/2.7.0/gems/actionpack-5.2.4.3/lib/action_dispatch/middleware/static.rb:127:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'\n/arvados/services/api/app/middlewares/arvados_api_token.rb:66:in `call'\n/cache/gem/ruby/2.7.0/gems/railties-5.2.4.3/lib/rails/engine.rb:524:in `call'\n/cache/gem/ruby/2.7.0/gems/rack-2.2.3/lib/rack/handler/webrick.rb:95:in `service'\n/usr/local/lib/ruby/2.7.0/webrick/httpserver.rb:140:in `service'\n/usr/local/lib/ruby/2.7.0/webrick/httpserver.rb:96:in `run'\n/usr/local/lib/ruby/2.7.0/webrick/server.rb:307:in `block in start_thread'\n","params":{"_profile":"true","async":"false","cluster_id":"","ensure_unique_name":"false","group_given":"true","help":"false","group":{}},"@timestamp":"2021-03-02T20:03:23.211772104Z","@version":"1","message":"[422] POST /arvados/v1/groups (Arvados::V1::GroupsController#create)"}
</pre>