Join 34,000+ subscribers and receive articles from our blog about software quality, testing, QA and security.
 

[Redmine][Resolved] Defect push time out after 30 sec


#1

Hi!

I get a time out error after 30 seconds when I submit a defect to Redmine. Here is a screenshot from the error:

http://i.imgur.com/bmAlbFd.png

I’ve modified the Redmine plugin to support custom fields and api key integration. Redmine receives the defect, and I can work with it in Redmine, but TestRail still times out. What could be the problem?

Screenshot of Firebug:
http://i.imgur.com/S7oplGk.png

Here are some logs from Redmines and Testrails apache server:

10.1.2.3 - - [08/Jun/2015:15:54:32 +0200] "GET /testrail/images/animations/progressStandard.gif HTTP/1.1" 304 - "http://10.1.2.3:82/testrail/css/app-combined.css?3315" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0 FirePHP/0.7.4"
10.1.2.3 - - [08/Jun/2015:15:54:54 +0200] "GET /testrail/images/animations/progressStandard.gif HTTP/1.1" 304 - "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0 FirePHP/0.7.4"
10.1.2.3 - - [08/Jun/2015:15:54:57 +0200] "POST /testrail/index.php?/tests/ajax_reload_timer HTTP/1.1" 200 371 "http://10.1.2.3:82/testrail/index.php?/tests/view/47&group_by=cases:section_id&group_order=asc&group_id=14" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0 FirePHP/0.7.4"

==> ./redmine26-logs/access_log <==
10.1.2.3 - - [08/Jun/2015:15:54:32 +0200] "POST /redmine/issues.json HTTP/1.1" 201 1030

==> ./testrail-log/access_log <==
10.1.2.3 - - [08/Jun/2015:15:54:32 +0200] "POST /testrail/index.php?/defects/ajax_push HTTP/1.1" 200 138 "http://10.1.2.3:82/testrail/index.php?/tests/view/47&group_by=cases:section_id&group_order=asc&group_id=14" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0 FirePHP/0.7.4"

And logs from TestRail:

[E] 2015-06-08 16:27:11 [30137ms]: [HttpException] Operation timed out after 30000 milliseconds with 0 bytes received
---
Details: <missing>
File: /var/www/html/testrail/sys/helpers/ex.php
Line: 25
Status Code: 500
Host: 10.3.1.152:82
Uri: /testrail/index.php?/defects/ajax_push (POST)
---
Browser: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0 FirePHP/0.7.4
PHP: 5.3.3
Server: Linux 2.6.32-504.el6.x86_64 #1 SMP Wed Oct 15 04:27:16 UTC 2014 x86_64
---
status_id: 1
assignedto: <empty>
comment: <empty>
attachments: <empty>
version: <empty>
elapsed: <empty>
defects: <empty>
project_id: 2
test_ids: 47
_token: 5.Bu..PYPS72x4QfLSc/
_version: 4.2.0.3315
defect_subject: Failed test: Kártyaszám töredék beírása; helyes
defect_tracker: 1
defect_project: 2
defect_category: <empty>
defect_os: <empty>
defect_ostype: <empty>
defect_reproducibility: <empty>
defect_severity: <empty>
defect_stepstoreproduce: <empty>
defect_description: T47: Kártyaszám töredék beírása; helyes
http://10.3.1.152:82/testrail/index.php?/tests/view/47

---
Trace:
at ex::raise (ex.php:25)
at ex::raise (http.php:219)
at http::request_ex (Redmine_custom.php:699)
at Redmine_api->_send_request (Redmine_custom.php:667)
at Redmine_api->_send_command (Redmine_custom.php:853)
at Redmine_api->add_issue (Redmine_custom.php:497)
at Redmine_custom_defect_plugin->push (defects.php:1051)
at Defects_controller->ajax_push (controller.php:215)
at Controller->_invoke_web_call (controller.php:127)
at Controller->_invoke_web (controller.php:76)
at Controller->_invoke (gizmo.php:107)
at require_once (index.php:106)

Thanks in advance!


#2

Well, first of all, I assume that Redmine itself works fine? I mean, if you perform the same request manually via Firebug, it doesn’t take over 30 seconds, and pushing the request via TestRail does actually save the bug?

It feels like there might be a bug with either the plugin or the mysterious http class. From the log it looks like POST /redmine/issues.json returns HTTP 201 Created response, which doesn’t have to have a body. Maybe the plugin treats absence of body as no response. I cannot help you to debug this, but I’d suggest that first of all you try the request manually and check whether the response is empty, and then look inside what http::request_ex() method does (apparently some magic with the curl handle but not enough of it).


#3

I pushed the request via a rest client and it took about 30.247915 seconds.

Response headers:

Status Code: 201 Created
Cache-Control: max-age=0, private, must-revalidate
Connection: close
Content-Type: application/json; charset=utf-8
Date: Tue, 09 Jun 2015 12:22:39 GMT
Etag: "2e4b4818336e02f4b24fa84d0b777ecc"
Location: http://10.1.2.3:81/redmine/issues/58
Server: Apache

Set-Cookie: _redmine_session=BAh7DEkiDHVzZXJfaWQGOgZFRmkGSSIKY3RpbWUGOwBGbCsHUdB2VUkiCmF0aW1lBjsARmwrB4%2FadlVJIg9zZXNzaW9uX2lkBjsAV
EkiJTBmZDBhNzcxYjc4ZWQ0OGY5ZWU4NmNjOWVjNjAwYTU3BjsAVEkiEF9jc3JmX3Rva2VuBjsARkkiMVNCVS95Smkya1hWUkl5SEJMZENJSjFoY2g0Vm5rW
nNuSmdHL3NyTFUvY1E9BjsARkkiCnF1ZXJ5BjsARnsJOg9wcm9qZWN0X2lkMDoMZmlsdGVyc3sGSSIOc3RhdHVzX2lkBjsAVHsHOg1vcGVyYXRvckkiBm8GO
wBUOgt2YWx1ZXNbBkkiAAY7AFQ6DWdyb3VwX2J5MDoRY29sdW1uX25hbWVzMEkiFmlzc3Vlc19pbmRleF9zb3J0BjsARkkiDGlkOmRlc2MGOwBU--43ec12b873fe01f7cf790101fd2c7c02ef996c01; path=/; HttpOnly

Status: 201 Created
Transfer-Encoding: chunked
X-Frame-Options: SAMEORIGIN
X-Powered-By: Phusion Passenger 5.0.6
X-Rack-Cache: invalidate, pass
X-Request-Id: 9e7aa0b6ba272c56a5deceaee3fbd9b4
X-Runtime: 30.247915
X-UA-Compatible: IE=Edge,chrome=1

The response does have a body, it contains the created issue in json format.

It looks like Redmine is causing the problem.

Edit: Yes, I turned off the e-mail notifications when an issue is created, and it repsonses almost instantly.


#4

Heh… Well, email notifications do sound important. You might want to raise this issue with Redmine devs.

Meanwhile, another way to try to work around this is to increase timeout to e.g. 60 seconds in the plugin with curl_setopt($_curl, CURLOPT_TIMEOUT, 60); before sending the request (if it’s not overridden inside http functions — then it would require rewriting the request part with raw curl)


#5

They know this, I’ve read it in their FAQ. I’m currently using a temporary Redmine installation (so I can tinker with it), and it doesn’t have a configured mail server. I guess Redmine tried to send a mail, but he couldn’t, then gave up after 30 secs.

I did try that yesterday, but it did not have any effect.

Thank you for your reply!


#6

Hi all,

Great to hear that you got it working already! The http class (curl wrapper) and defect plugins use a timeout of 30 seconds per request currently and TestRail assumes that requests that take longer than that wouldn’t return (so it aborts them). You wouldn’t usually see this behavior except when there’s a problem with the issue tracker installation (JIRA, Redmine, etc.) or a network connection timeout, for example.

Regards,
Tobias