I have the following tech stack:
Both Agile plugin and Easy Gantt plugin contain drag&drop visual UI, and dropping an item results in the PUT request. I don't know whether Redmine has any use of PUT requests anywhere apart from those plugins.
Problem is, these PUT requests are extremely slow for no obvious reason. They take ~120000 ms (120 sec, 2 minutes) to complete.
Here's log from log/production.log:
Started PUT "/agile/board" for 127.0.0.1 at 2016-10-23 20:08:03 +0300
Processing by AgileBoardsController#update as */*
Parameters: {"issue"=>{"status_id"=>"3"}, "positions"=>{"2"=>{"position"=>"0"}}, "id"=>"2"}
Current user: admin (id=1)
Rendered mailer/_issue.text.erb (4.8ms)
Rendered mailer/issue_edit.text.erb within layouts/mailer (8.2ms)
Rendered mailer/_issue.html.erb (1.3ms)
Rendered mailer/issue_edit.html.erb within layouts/mailer (4.3ms)
Rendered plugins/redmine_agile/app/views/agile_boards/_issue_card.html.erb (35.0ms)
Completed 200 OK in 120519ms (Views: 33.0ms | ActiveRecord: 41.0ms)
Here the date is at the moment of initiating the PUT request. So, what RoR did all these 2 minutes, if it rendered view in 33ms and worked with ActiveRecords in 41ms? What other activity could it perform which I can look at?
Here is the request headers from Firebug:
Host: redmine.local
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0
Accept: */*
Accept-Language: ru,ru-RU;q=0.8,en-US;q=0.5,en;q=0.3
Accept-Encoding: gzip, deflate
X-CSRF-Token: ZKCHb1NeenfN6EVttTPHMiGItsTsKWDJPm5Q2VqaiYRRn420TH67pnwfRpWo/mQdDOWDhZNe1snDy+eP327PfQ==
Content-Type: application/x-www-form-urlencoded; charset=UTF-8
X-Requested-With: XMLHttpRequest
Referer: http://redmine.local/projects/myproject/agile/board
Content-Length: 60
Cookie: _redmine_session=MjI1Q <... lots of data ...>f
X-Compress: 1
Proxy-Authorization: c7f14568a48248797f198ea6e3c7d7c4f39185ce12aeac08439a9d6726a4cfd5612d4cef98c0ca43
Connection: keep-alive
Here is the answer from server:
Cache-Control: max-age=0, private, must-revalidate
Connection: keep-alive
Content-Encoding: gzip
Content-Type: text/html; charset=utf-8
Date: Sun, 23 Oct 2016 17:10:03 GMT
Etag: W/"0ec2e6c508ed9d99f224fc23e1fd3dbf"
Server: nginx/1.10.1 + Phusion Passenger 5.0.30
Set-Cookie: _redmine_session=VlZkakNTT <... lots of data ...>1f08a39ea5c63; path=/; HttpOnly
Transfer-Encoding: chunked
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Request-Id: 30b3a5f8-edb0-419a-b5f1-c6603439438a
X-Runtime: 120.523361
X-XSS-Protection: 1; mode=block
status: 200 OK
x-powered-by: Phusion Passenger 5.0.30
In the answer from server "Date" field shows 2 minutes from the moment of starting the PUT request, so I guess that server starts building this answer after those 2 minutes of... what?
In the timings panel of Firebug there's three zeroes for DNS resolving, connection and sending (I am connecting to my local server on the same machine), 120525ms waiting and 8ms receiving.
Here's the log record for this request from Nginx access.log:
127.0.0.1 - - [23/Oct/2016:20:10:03 +0300] "PUT /agile/board HTTP/1.1" 200 920 "http://redmine.local/projects/myproject/agile/board" "Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0"
I tried to replace Nginx+Passenger stack with Apache2+Passenger one, but problem persists. Even when I start the Webrick the 2 minutes timeout is there, so I believe it's either something with RoR, not the web server.
I have no prior experience writing the Ruby on Rails applications, only installing them.
Problem was that after_save was sending e-mails through sendmail and sendmail was stuck on the relatively well-known error "My unqualified host name (your hostname here) unknown; sleeping for retry". After I googled about this error and ensured that the correct FQN for my hostname was in the /etc/hosts, 2 minutes delay became 2 seconds delay.
127.0.0.1 localhost localhost.localdomain my-host-name