Hello Marcel,

we recognized this problem, too. We’ve upgraded from 4.2.6 to 5.0.18. The upgrade was without any errors.

What we’ve figured out are the following points:

- it just happens with firefox (47 actually), with chrome it works

- not all users are affected (two of three users are effected)

- production log doesnt show any errors
- Error 500

We also use CentOS and updated to the newest version after upgrading OP.

Could you please look in your production.log. Are there any errors?

i hope this can be fixed, else we must go back to 4.2.6

web.log
E, [2016-06-13T07:59:02.399287 #7572] ERROR -- : app error: METHOD_OTHER, accepted HTTP methods are OPTIONS, GET, HEAD, POST, PUT, DELETE, TRACE, CONNECT, PROPFIND, PROPPATCH, MKCOL, COPY, MOVE, LOCK, UNLOCK, VERSION-CONTROL, REPORT, CHECKOUT, CHECKIN, UNCHECKOUT, MKWORKSPACE, UPDATE, LABEL, MERGE, BASELINE-CONTROL, MKACTIVITY, ORDERPATCH, ACL, SEARCH, MKCALENDAR, and PATCH (ActionController::UnknownHttpMethod) E, [2016-06-13T07:59:02.399422 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.5.2/lib/action_dispatch/http/request.rb:344:in `check_method' E, [2016-06-13T07:59:02.399493 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.5.2/lib/action_dispatch/http/request.rb:105:in `request_method' E, [2016-06-13T07:59:02.399538 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:51:in `started_request_message' E, [2016-06-13T07:59:02.399599 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:37:in `block in call_app' E, [2016-06-13T07:59:02.399631 #7572] ERROR -- : /opt/openproject/vendor/ruby-2.1.6/lib/ruby/2.1.0/logger.rb:372:in `add' E, [2016-06-13T07:59:02.399662 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/activerecord-session_store-0.1.1/lib/active_record/session_store/extension/logger_silencer.rb:34:in `add_with_threadsafety' E, [2016-06-13T07:59:02.399693 #7572] ERROR -- : /opt/openproject/vendor/ruby-2.1.6/lib/ruby/2.1.0/logger.rb:434:in `info' E, [2016-06-13T07:59:02.399723 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:37:in `call_app' E, [2016-06-13T07:59:02.399753 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:20:in `block in call' E, [2016-06-13T07:59:02.399803 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.5.2/lib/active_support/tagged_logging.rb:68:in `block in tagged' E, [2016-06-13T07:59:02.399834 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.5.2/lib/active_support/tagged_logging.rb:26:in `tagged' E, [2016-06-13T07:59:02.399864 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.5.2/lib/active_support/tagged_logging.rb:68:in `tagged' E, [2016-06-13T07:59:02.399893 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/rack/logger.rb:20:in `call' E, [2016-06-13T07:59:02.399923 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/request_store-1.1.0/lib/request_store/middleware.rb:8:in `call' E, [2016-06-13T07:59:02.399974 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/request_id.rb:21:in `call' E, [2016-06-13T07:59:02.400005 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/methodoverride.rb:22:in `call' E, [2016-06-13T07:59:02.400035 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/runtime.rb:18:in `call' E, [2016-06-13T07:59:02.400084 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.5.2/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call' E, [2016-06-13T07:59:02.400119 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.5.2/lib/action_dispatch/middleware/static.rb:116:in `call' E, [2016-06-13T07:59:02.400164 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/sendfile.rb:113:in `call' E, [2016-06-13T07:59:02.400194 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/engine.rb:518:in `call' E, [2016-06-13T07:59:02.400225 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/application.rb:165:in `call' E, [2016-06-13T07:59:02.400256 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/railtie.rb:194:in `public_send' E, [2016-06-13T07:59:02.400305 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/railties-4.2.5.2/lib/rails/railtie.rb:194:in `method_missing' E, [2016-06-13T07:59:02.400336 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/bundler/gems/rack-protection-5a7d1bd2f05c/lib/rack/protection/frame_options.rb:31:in `call' E, [2016-06-13T07:59:02.400365 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/bundler/gems/rack-protection-5a7d1bd2f05c/lib/rack/protection/json_csrf.rb:18:in `call' E, [2016-06-13T07:59:02.400395 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/urlmap.rb:66:in `block in call' E, [2016-06-13T07:59:02.400451 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `each' E, [2016-06-13T07:59:02.400521 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `call' E, [2016-06-13T07:59:02.400554 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:580:in `process_client' E, [2016-06-13T07:59:02.400584 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:674:in `worker_loop' E, [2016-06-13T07:59:02.400614 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:529:in `spawn_missing_workers' E, [2016-06-13T07:59:02.400644 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/unicorn-4.9.0/lib/unicorn/http_server.rb:140:in `start' E, [2016-06-13T07:59:02.400720 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/gems/unicorn-4.9.0/bin/unicorn:126:in `<top (required)>' E, [2016-06-13T07:59:02.400752 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/bin/unicorn:23:in `load' E, [2016-06-13T07:59:02.400781 #7572] ERROR -- : /opt/openproject/vendor/bundle/ruby/2.1.0/bin/unicorn:23:in `<main>'

Hi Marc, Marcel,

judging from the log output from Marc, the request to update a single work package (PATCH) isn’t working properly. The web log output you mention suggests that Rails rejects the request since the request is passed to our application server with the METHOD_OTHER HTTP method.

Do you use our packaged apache web server, or use your own web server (e.g., nginx), or some other kind of request preprocessing ? (Load balancer, Proxy, … )
I assume that something is rewriting our PATCH request before it lands on the Rails application server, since the screenshot you share is clearly marked as a PATCH request, and Rails receives something different.

Best,
Oliver

Hi Oliver,

thanks for your fast reply. We are using apache httpd. / Squid as Proxy

with kind regards,
Marc

Hi Oliver,
thank you for fast reply too. We are using clean new installation of apache httpd. Now I have only first test project in DB so I could reinstall anything if it helps.

Hello guys,

we’ve figured out what the problem is.

As i said we use squid as a Proxy. We already had added the Open Project URL as an exception, which should be ignored by the Proxy.

But Firefox was misconfigured, so it used the proxy with OpenProject. It wasnt a browser specific problem.

So it could be fixed by telling the browser to automatically recognize proxy settings and not to use the proxy settings from the system or just add your OP URL as an expcetion.

Thank you for your support.

with kind regards
Marc Vollmer

Hey Marc,

great to hear you could resolve the issue!

@Marcel: Are you affected by the same issue?

Best,
Oliver

Hi Oliver
I was some days busy with other project, but now I’m back in openproject.

Unfortunately it’s not the same in our case. We didn’t use proxy.

I have tried to reinstall openproject and I found some error (warnings) regarding apache2. Could i have some relation to “internal server error”?:

[apache2] ./bin/postinstall
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/server/rewrite_mod.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/vhost/compression.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/vhost/expiration.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/vhost/sys.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/vhost/assets.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/server/proxy_mod.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/server/proxy_http_mod.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/server/headers_mod.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/server/expires_mod.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/server/deflate_mod.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/openproject/addons/apache2/includes/server/filter_mod.conf’
chcon: can’t apply partial context to unlabeled file ‘/etc/httpd/conf.d/openproject.conf’
Redirecting to /bin/systemctl restart httpd.service
[repositories] ./bin/postinstall
No repositories have been configured. Skipping configuration.
[smtp] ./bin/postinstall
[memcached] ./bin/postinstall
[openproject] ./bin/postinstall

***** Seeding for locale: ‘en’

***** Seeding basic data
↳ BuiltinRolesSeeder
***** Skipping built in role Non member - already exists
***** Skipping built in role Anonymous - already exists
↳ RoleSeeder
***** Skipping roles as there are already some configured
↳ ActivitySeeder
***** Skipping activities as there are already some configured
↳ ColorSeeder
***** Skipping colors as there are already some configured
↳ WorkflowSeeder
***** Skipping types, statuses and workflows as there are already some configured
↳ PrioritySeeder
***** Skipping priorities as there are already some configured
↳ ProjectStatusSeeder
***** Skipping reported project status as there are already some configured
↳ ProjectTypeSeeder
***** Skipping project types as there are already some configured
↳ SettingSeeder
***** Skipping settings as all settings already exist in the db
Loading discovered seeders:
↳ EnumerationsSeeder

***** Seeding admin user
***** No need to seed an admin as there already is one.

***** Seeding demo data
↳ ProjectSeeder
***** Skipping DemoData::ProjectSeeder

***** Loading bourbon_engine seed data

***** Loading prototype_rails_engine seed data

***** Loading openproject_translations seed data

***** Loading openproject_global_roles seed data

***** Loading openproject_auth_plugins seed data

***** Loading openproject_auth_saml seed data

***** Loading lobby_boy seed data

***** Loading openproject_openid_connect seed data

***** Loading openproject_documents seed data

***** Loading openproject_help_link seed data

***** Loading openproject_announcements seed data

***** Loading openproject_my_project_page seed data

***** Loading openproject_xls_export seed data

***** Loading reportingengine seed data

***** Loading openproject_costs seed data

***** Loading openproject_reporting seed data

***** Loading openproject_meeting seed data

***** Loading openproject_pdf_export seed data

***** Loading openproject_backlogs seed data

**** Loading production seed data

***** settings

**** Skipping settings as there are already some configured

***** Loading openproject_themes_dark seed data

***** Loading openproject_local_avatars seed data

***** Loading openproject_webhooks seed data

***** Loading openproject_github_integration seed data
Nothing to do.
Nothing to do.
Redirecting to /bin/systemctl restart openproject.service

OK. I just found out that it works when I use default english language in setting of my openproject account. It seems that problem is related to non-english translation.

Hi Marcel,

from the first lines of the configure output, it seems that it doesn’t correctly apply the SELinux contexts. It may be related to your problem.

Could you dig through the /var/log/openproject/production.log to find the actual log line that causes the internal server error and paste it here?

Best,
Oliver

I found some lines wit internal error information:

I, [2016-06-25T06:34:18.898451 #24571] INFO — : Parameters: {“utf8”=>“✓”, “authenticity_token”=>“2K7U2L+bpEZSTltGLZvOfrOTqmLGcGV9XYug2G5nBswBIGwrYXsv57LX+tNWKzSn6nNQ237rP5qIC1J71zfu4g==”, “user”=>{“mail”=>“cekel@amiplus.sk”, “firstname”=>“Slavomír”, “lastname”=>“Čekeľ”, “admin”=>“0”}, “continue”=>“”}
I, [2016-06-25T06:34:18.924601 #24571] INFO — : Completed 500 Internal Server Error in 26ms (ActiveRecord: 3.7ms)
F, [2016-06-25T06:34:18.926927 #24571] FATAL — :
ActiveRecord::StatementInvalid (Mysql2::Error: Incorrect string value: ‘\xC4\x8Ceke\xC4…’ for column ‘lastname’ at row 1: INSERT INTO `users` (`type`, `language`, `mail_notification`, `firstname`, `lastname`, `mail`, `login`, `status`, `created_on`, `updated_on`) VALUES (‘User’, ‘sk’, ‘only_my_events’, ‘Slavomír’, ‘Čekeľ’, ‘cekel@amiplus.sk’, ‘cekel@amiplus.sk’, 4, ‘2016-06-25 10:34:18’, ‘2016-06-25 10:34:18’)):
app/controllers/concerns/user_invitation.rb:140:in `block in user_invitation’
app/controllers/concerns/user_invitation.rb:135:in `user_invitation’
app/controllers/concerns/user_invitation.rb:118:in `invite_user!’
app/controllers/users_controller.rb:124:in `create’
app/middleware/reset_current_user.rb:47:in `call’
app/middleware/params_parser_with_exclusion.rb:40:in `call’

OR
——————————————————————-
I, [2016-06-25T06:51:22.717546 #24571] INFO — : Parameters: {“utf8”=>“✓”, “authenticity_token”=>“oJWgCH5NBVEX1B1MxyTtQ7WYrxC0Zd15QGeciD71WYh5Gxj7oK2O8PdNvNm8lBea7HhVqQz+h56V524rh6Wxpg==”, “timeline”=>{“name”=>“Prehľad úloh”, “options”=>{“exist”=>“”, “zoom_factor”=>“4”, “initial_outline_expansion”=>“1”, “timeframe_start”=>“2016-06-15”, “timeframe_end”=>“2016-07-31”, “columns”=>[“start_date,due_date,status,responsible”], “project_sort”=>“0”, “compare_to_relative”=>“”, “compare_to_relative_unit”=>“0”, “compare_to_absolute”=>“”, “vertical_planning_elements”=>“”, “exclude_own_planning_elements”=>“0”, “planning_element_status”=>[“”], “planning_element_types”=>[“”], “planning_element_responsibles”=>[“”], “planning_element_assignee”=>[“”], “exclude_reporters”=>“yes”, “exclude_empty”=>“no”, “project_types”=>[“”], “project_status”=>[“”], “project_responsibles”=>[“”], “parents”=>[“”], “planning_element_time_types”=>[“”], “planning_element_time_absolute_one”=>“”, “planning_element_time_absolute_two”=>“”, “planning_element_time_relative_one”=>“”, “planning_element_time_relative_one_unit”=>“0”, “planning_element_time_relative_two”=>“”, “planning_element_time_relative_two_unit”=>“0”, “grouping_one_enabled”=>“no”, “grouping_one_selection”=>[“”], “grouping_one_sort”=>“0”, “hide_other_group”=>“no”}}, “button”=>“”, “project_id”=>“peva-06-07-2016”}
I, [2016-06-25T06:51:22.757360 #24571] INFO — : Completed 500 Internal Server Error in 40ms (ActiveRecord: 3.9ms)
F, [2016-06-25T06:51:22.758774 #24571] FATAL — :
ActiveRecord::StatementInvalid (Mysql2::Error: Incorrect string value: ‘\xC4\xBEad \xC3…’ for column ‘name’ at row 1: INSERT INTO `timelines` (`options`, `name`, `project_id`, `created_at`, `updated_at`) VALUES (‘—- !ruby/hash:ActionController::Parameters\nexist: \’\‘\nzoom_factor: \’4\’\ninitial_outline_expansion: \‘1\’\ntimeframe_start: \‘2016-06-15\’\ntimeframe_end: \‘2016-07-31\’\ncolumns:\n- start_date\n- due_date\n- status\n- responsible\nproject_sort: \‘0\’\ncompare_to_relative: \‘\’\ncompare_to_relative_unit: \‘0\’\ncompare_to_absolute: \‘\’\nvertical_planning_elements: \‘\’\nexclude_own_planning_elements: \‘0\’\nexclude_reporters: \‘yes\’\nexclude_empty: \‘no\’\nplanning_element_time_absolute_one: \‘\’\nplanning_element_time_absolute_two: \‘\’\nplanning_element_time_relative_one: \‘\’\nplanning_element_time_relative_one_unit: \‘0\’\nplanning_element_time_relative_two: \‘\’\nplanning_element_time_relative_two_unit: \‘0\’\ngrouping_one_enabled: \‘no\’\ngrouping_one_sort: \‘0\’\nhide_other_group: \‘no\’\n’, ‘Prehľad úloh’, 4, ‘2016-06-25 10:51:22’, ‘2016-06-25 10:51:22’)):
app/controllers/timelines_controller.rb:61:in `create’
app/middleware/reset_current_user.rb:47:in `call’
app/middleware/params_parser_with_exclusion.rb:40:in `call’

I found that when I replace character as ‘č’, ‘ť’ …. INSERT and UPDATE works well and I have no “internal errors”.

I assume you used an existing database that does not use UTF-8 charset. This is not an error of OpenProject, which will employ UTF-8 db encodings by default. Please convert it manually:

ALTER TABLE <dbname>.<tablename> CONVERT TO CHARACTER SET utf8

Best,
Oliver

Hi Oliver,

I did it for all tables in DB but it didn’t help. As we work on first test project I decided to reinstall openproject from scratch and now it works without problem.

Thank you for the help and support.