Defect #12496

Updates through REST API return status 200 response but still fail

Added by Adam Lacoste over 9 years ago. Updated over 9 years ago.

Status:NewStart date:
Priority:NormalDue date:
Assignee:-% Done:

0%

Category:REST API
Target version:-
Resolution:Cant reproduce Affected version:2.0.4

Description

I am building an internal application for my company which depends on being able to read and update Redmine issues. Although the REST API's GET behavior appears to be working perfectly fine, my attempts to PUT data to Redmine always fail. I discussed this with another developer who previously had done some simple Redmine integration and we found that the little app he had written, which used to be able to send updates to Redmine, now did not work at all either. We believe this is a result of our recent upgrade to 2.0.4, but this is only speculation.

To narrow the possible factors which could cause problems, I have been attempting to test the REST API update feature using cURL. Here's an example. (Domains and IPs obscured for privacy and to get past the spam filter.)

Request:

curl -v -H "Content-Type: application/json" -X PUT --data '{ "issue": { "subject": "Example subject linke" } }' -u username:password DOMAIN/issues/12345.json
* About to connect() to DOMAIN port 80 (#0)
*   Trying IP_ADDR... connected
* Connected to DOMAIN (IP_ADDR) port 80 (#0)
* Server auth using Basic with user 'username'
> PUT /issues/12345.json HTTP/1.1
> Authorization: Basic YnVpbGRkdWRlOkJ1MTFk
> User-Agent: curl/7.21.4 (universal-apple-darwin11.0) libcurl/7.21.4 OpenSSL/0.9.8r zlib/1.2.5
> Host: DOMAIN
> Accept: */*
> Content-Type: application/json
> Content-Length: 88
> 
< HTTP/1.1 200 OK
< Date: Mon, 03 Dec 2012 22:14:47 GMT
< Server: Apache/2.2.22 (Debian)
< X-Powered-By: Phusion Passenger (mod_rails/mod_rack) 3.0.18
< X-UA-Compatible: IE=Edge,chrome=1
< ETag: "7215ee9c7d9dc229d2921a40e899ec5f" 
< Cache-Control: max-age=0, private, must-revalidate
< X-Request-Id: fc14a612df055c426e5b93090d3210c6
< X-Runtime: 0.196459
< X-Rack-Cache: invalidate, pass
< Set-Cookie: _redmine_session=BAh7BkkiD3Nlc3Npb25faWQGOgZFRkkiJTgxMGNiYTRjNWM3YWI2MDM0MmZiMjZkMDA4ZTBmZWIwBjsAVA%3D%3D--1a77c7214ab3dff0d1c7facff14dfe92338f276f; path=/; HttpOnly
< Set-Cookie: autologin=; path=/; expires=Thu, 01-Jan-1970 00:00:00 GMT
< Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT
< Access-Control-Allow-Headers: Content-Type, Authorization
< Status: 200
< Access-Control-Allow-Origin: *
< Content-Length: 1
< Content-Type: application/json; charset=utf-8
< 
* Connection #0 to host DOMAIN left intact
* Closing connection #0

That last line there is the empty space response Redmine sends back, along with the status 200.

When I go and check the issue I just updated in Redmine's issue browser, the subject has not changed, but I'll be told that the issue was updated less than a minute ago.

I've tried this with several different fields (description, status, project). I've tried it as JSON and XML. I've tried authenticating using a username/password and by using the app key. Nothing works.

Here are some additional details about our Redmine setup:

Environment:
  Redmine version                          2.0.4.stable.10796
  Ruby version                             1.9.3 (x86_64-linux)
  Rails version                            3.2.6
  Environment                              production
  Database adapter                         Mysql2
Redmine plugins:
  redmine_backlogs                         v0.9.26
  redmine_code_review                      0.5.0
  redmine_custom_workflows                 0.0.4
  redmine_embedded                         0.0.2
  redmine_fix_title                        0.0.1
  redmine_impasse                          1.2.2
  redmine_issue_templates                  0.0.3
  redmine_query_current_sprint             0.0.1
  redmine_wiki_issue                       0.0.1

History

#1 Updated by Jean-Philippe Lang over 9 years ago

That would be nice to have the Redmine log with log level set to debug that is generated when you do this request.

#2 Updated by Adam Lacoste over 9 years ago

I'll work with our RM support guy to get this.

#3 Updated by Adam Lacoste over 9 years ago

Whoops, wrong part of the log, stand by

#4 Updated by Adam Lacoste over 9 years ago

This appears to be the correct segment of the log:

Started PUT "/issues/18073.json" for 130.80.28.6 at 2012-12-04 13:54:43 -0500

Started GET "/my/page" for 130.80.9.118 at 2012-12-04 13:54:43 -0500
Processing by IssuesController#update as JSON
  Parameters: {"id"=>"18073"}
WARNING: Can't verify CSRF token authenticity
Processing by MyController#page as HTML
   (0.9ms)  SELECT MAX(`settings`.`updated_on`) AS max_id FROM `settings` 
  Setting Load (0.9ms)  SELECT `settings`.* FROM `settings` WHERE `settings`.`name` = 'rest_api_enabled' LIMIT 1
   (1.4ms)  SELECT MAX(`settings`.`updated_on`) AS max_id FROM `settings` 
  User Load (1.4ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`login` = 'builddude'
  User Load (0.8ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 252 AND (users.status = 1) LIMIT 1
   (6.4ms)  BEGIN
   (8.3ms)  UPDATE `users` SET `last_login_on` = '2012-12-04 13:54:43', `updated_on` = '2012-12-04 13:54:43' WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 252
  CustomField Load (0.5ms)  SELECT `custom_fields`.* FROM `custom_fields` WHERE (type = 'UserCustomField') ORDER BY position
  UserPreference Load (2.5ms)  SELECT `user_preferences`.* FROM `user_preferences` WHERE `user_preferences`.`user_id` = 252 LIMIT 1
  SQL (2.1ms)  SELECT `custom_values`.`id` AS t0_r0, `custom_values`.`customized_type` AS t0_r1, `custom_values`.`customized_id` AS t0_r2, `custom_values`.`custom_field_id` AS t0_r3, `custom_values`.`value` AS t0_r4, `custom_fields`.`id` AS t1_r0, `custom_fields`.`type` AS t1_r1, `custom_fields`.`name` AS t1_r2, `custom_fields`.`field_format` AS t1_r3, `custom_fields`.`possible_values` AS t1_r4, `custom_fields`.`regexp` AS t1_r5, `custom_fields`.`min_length` AS t1_r6, `custom_fields`.`max_length` AS t1_r7, `custom_fields`.`is_required` AS t1_r8, `custom_fields`.`is_for_all` AS t1_r9, `custom_fields`.`is_filter` AS t1_r10, `custom_fields`.`position` AS t1_r11, `custom_fields`.`searchable` AS t1_r12, `custom_fields`.`default_value` AS t1_r13, `custom_fields`.`editable` AS t1_r14, `custom_fields`.`visible` AS t1_r15, `custom_fields`.`multiple` AS t1_r16 FROM `custom_values` LEFT OUTER JOIN `custom_fields` ON `custom_fields`.`id` = `custom_values`.`custom_field_id` WHERE `custom_values`.`customized_id` = 252 AND `custom_values`.`customized_type` = 'Principal' ORDER BY custom_fields.position
   (2.4ms)  COMMIT
  Issue Load (0.6ms)  SELECT `issues`.* FROM `issues` WHERE `issues`.`id` = 18073 LIMIT 1
  Project Load (0.4ms)  SELECT `projects`.* FROM `projects` WHERE `projects`.`id` IN (111)
  Tracker Load (0.3ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (2)
  IssueStatus Load (0.3ms)  SELECT `issue_statuses`.* FROM `issue_statuses` WHERE `issue_statuses`.`id` IN (1)
  User Load (0.7ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` IN (243)
  IssuePriority Load (0.4ms)  SELECT `enumerations`.* FROM `enumerations` WHERE `enumerations`.`type` IN ('IssuePriority') AND `enumerations`.`id` IN (14) ORDER BY enumerations.position ASC
  IssueCategory Load (0.4ms)  SELECT `issue_categories`.* FROM `issue_categories` WHERE `issue_categories`.`id` IN (355)
  EnabledModule Load (0.5ms)  SELECT name FROM `enabled_modules` WHERE `enabled_modules`.`project_id` = 111
  TimeEntryActivity Load (0.6ms)  SELECT `enumerations`.* FROM `enumerations` WHERE `enumerations`.`type` IN ('TimeEntryActivity') AND `enumerations`.`is_default` = 1 ORDER BY enumerations.position ASC LIMIT 1
  IssueCustomField Load (0.5ms)  SELECT `custom_fields`.* FROM `custom_fields` WHERE `custom_fields`.`type` IN ('IssueCustomField') AND (is_for_all=1) ORDER BY position
  IssueCustomField Load (0.4ms)  SELECT `custom_fields`.* FROM `custom_fields` INNER JOIN `custom_fields_projects` ON `custom_fields`.`id` = `custom_fields_projects`.`custom_field_id` WHERE `custom_fields`.`type` IN ('IssueCustomField') AND `custom_fields_projects`.`project_id` = 111 ORDER BY custom_fields.position
  IssueCustomField Load (0.7ms)  SELECT `custom_fields`.* FROM `custom_fields` INNER JOIN `custom_fields_trackers` ON `custom_fields`.`id` = `custom_fields_trackers`.`custom_field_id` WHERE `custom_fields`.`type` IN ('IssueCustomField') AND `custom_fields_trackers`.`tracker_id` = 2
  IssueStatus Load (0.6ms)  SELECT `issue_statuses`.* FROM `issue_statuses` WHERE `issue_statuses`.`id` = 1 LIMIT 1
  Role Load (0.6ms)  SELECT `roles`.* FROM `roles` 
  Workflow Load (1.4ms)  SELECT `workflows`.* FROM `workflows` WHERE `workflows`.`old_status_id` = 1 AND (role_id IN (1,2,3,4,5) AND tracker_id = 2 AND ((author = 0 AND assignee = 0)))
  IssueStatus Load (0.6ms)  SELECT `issue_statuses`.* FROM `issue_statuses` WHERE `issue_statuses`.`id` IN (11, 7, 8, 12, 2, 10, 3, 4, 6, 9, 13)
  IssueRelation Load (0.3ms)  SELECT `issue_relations`.* FROM `issue_relations` WHERE `issue_relations`.`issue_to_id` = 18073
   (0.3ms)  BEGIN
  Setting Load (0.4ms)  SELECT `settings`.* FROM `settings` WHERE `settings`.`name` = 'issue_done_ratio' LIMIT 1
  Tracker Load (3.1ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
  IssuePriority Load (0.4ms)  SELECT `enumerations`.* FROM `enumerations` WHERE `enumerations`.`type` IN ('IssuePriority') AND `enumerations`.`is_default` = 1 ORDER BY enumerations.position ASC LIMIT 1
   (1.8ms)  select version from schema_migrations where version like '%-redmine_backlogs'
  EnabledModule Load (0.6ms)  SELECT `enabled_modules`.* FROM `enabled_modules` WHERE `enabled_modules`.`project_id` = 111
  CACHE (0.0ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
  Issue Load (1.4ms)  SELECT `issues`.* FROM `issues` WHERE (root_id = 18073 and lft < 1 and rgt > 2 and tracker_id in (1,2)) ORDER BY lft DESC LIMIT 1
  CACHE (0.0ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
   (1.0ms)  SELECT SUM(COALESCE(remaining_hours, 0)) AS sum_id FROM `issues` WHERE `issues`.`root_id` = 18073 AND (`issues`.`lft` >= 1 AND `issues`.`rgt` <= 2) AND (`issues`.id != 18073) AND (`issues`.`rgt` - `issues`.`lft` = 1)
  CustomWorkflow Load (0.8ms)  SELECT `custom_workflows`.* FROM `custom_workflows` WHERE `custom_workflows`.`is_for_all` = 1 ORDER BY position ASC
  CustomWorkflow Load (0.4ms)  SELECT `custom_workflows`.* FROM `custom_workflows` INNER JOIN `custom_workflows_projects` ON `custom_workflows`.`id` = `custom_workflows_projects`.`custom_workflow_id` WHERE `custom_workflows_projects`.`project_id` = 111 ORDER BY position ASC
   (1.9ms)  UPDATE `issues` SET `updated_on` = '2012-12-04 13:54:44', `lock_version` = 26 WHERE (`issues`.`id` = 18073 AND `issues`.`lock_version` = 25)
  SQL (1.1ms)  SELECT `custom_values`.`id` AS t0_r0, `custom_values`.`customized_type` AS t0_r1, `custom_values`.`customized_id` AS t0_r2, `custom_values`.`custom_field_id` AS t0_r3, `custom_values`.`value` AS t0_r4, `custom_fields`.`id` AS t1_r0, `custom_fields`.`type` AS t1_r1, `custom_fields`.`name` AS t1_r2, `custom_fields`.`field_format` AS t1_r3, `custom_fields`.`possible_values` AS t1_r4, `custom_fields`.`regexp` AS t1_r5, `custom_fields`.`min_length` AS t1_r6, `custom_fields`.`max_length` AS t1_r7, `custom_fields`.`is_required` AS t1_r8, `custom_fields`.`is_for_all` AS t1_r9, `custom_fields`.`is_filter` AS t1_r10, `custom_fields`.`position` AS t1_r11, `custom_fields`.`searchable` AS t1_r12, `custom_fields`.`default_value` AS t1_r13, `custom_fields`.`editable` AS t1_r14, `custom_fields`.`visible` AS t1_r15, `custom_fields`.`multiple` AS t1_r16 FROM `custom_values` LEFT OUTER JOIN `custom_fields` ON `custom_fields`.`id` = `custom_values`.`custom_field_id` WHERE `custom_values`.`customized_id` = 18073 AND `custom_values`.`customized_type` = 'Issue' ORDER BY custom_fields.position
  Tracker Load (0.6ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
  IssuePriority Load (0.6ms)  SELECT `enumerations`.* FROM `enumerations` WHERE `enumerations`.`type` IN ('IssuePriority') AND `enumerations`.`is_default` = 1 ORDER BY enumerations.position ASC LIMIT 1
   (0.9ms)  select version from schema_migrations where version like '%-redmine_backlogs'
  CACHE (0.0ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
  Issue Load (1.0ms)  SELECT `issues`.* FROM `issues` WHERE (root_id=18073 and lft>1 and rgt<2 and
 (
 (NULL is NULL and not fixed_version_id is NULL)
 or
 (not NULL is NULL and fixed_version_id is NULL)
 or
 (not NULL is NULL and not fixed_version_id is NULL and NULL<>fixed_version_id)
 ))
   (0.8ms)  update issues
 set tracker_id = 4
 where root_id = 18073 and lft > 1 and rgt < 2
  CACHE (0.0ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
  Issue Load (1.0ms)  SELECT `issues`.* FROM `issues` WHERE (root_id = 18073 and lft < 1 and rgt > 2 and tracker_id in (1,2)) ORDER BY lft DESC LIMIT 1
  CustomWorkflow Load (1.1ms)  SELECT `custom_workflows`.* FROM `custom_workflows` WHERE `custom_workflows`.`is_for_all` = 1 ORDER BY position ASC
   (0.7ms)  COMMIT
Completed 200 OK in 1322ms (ActiveRecord: 109.9ms)
   (0.7ms)  SELECT `users`.id FROM `users` INNER JOIN `groups_users` ON `users`.`id` = `groups_users`.`group_id` WHERE `users`.`type` IN ('Group') AND `groups_users`.`user_id` = 252
   (1.4ms)  SELECT COUNT(DISTINCT `issues`.`id`) FROM `issues` LEFT OUTER JOIN `projects` ON `projects`.`id` = `issues`.`project_id` LEFT OUTER JOIN `issue_statuses` ON `issue_statuses`.`id` = `issues`.`status_id` WHERE `issues`.`assigned_to_id` IN (252, 10, 62, 119) AND (projects.status=1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) AND (issue_statuses.is_closed = 0)
  CACHE (0.0ms)  SELECT `users`.id FROM `users` INNER JOIN `groups_users` ON `users`.`id` = `groups_users`.`group_id` WHERE `users`.`type` IN ('Group') AND `groups_users`.`user_id` = 252
  SQL (1.4ms)  SELECT `issues`.`id` AS t0_r0, `issues`.`tracker_id` AS t0_r1, `issues`.`project_id` AS t0_r2, `issues`.`subject` AS t0_r3, `issues`.`description` AS t0_r4, `issues`.`due_date` AS t0_r5, `issues`.`category_id` AS t0_r6, `issues`.`status_id` AS t0_r7, `issues`.`assigned_to_id` AS t0_r8, `issues`.`priority_id` AS t0_r9, `issues`.`fixed_version_id` AS t0_r10, `issues`.`author_id` AS t0_r11, `issues`.`lock_version` AS t0_r12, `issues`.`created_on` AS t0_r13, `issues`.`updated_on` AS t0_r14, `issues`.`start_date` AS t0_r15, `issues`.`done_ratio` AS t0_r16, `issues`.`estimated_hours` AS t0_r17, `issues`.`parent_id` AS t0_r18, `issues`.`root_id` AS t0_r19, `issues`.`lft` AS t0_r20, `issues`.`rgt` AS t0_r21, `issues`.`position` AS t0_r22, `issues`.`remaining_hours` AS t0_r23, `issues`.`is_private` AS t0_r24, `issues`.`story_points` AS t0_r25, `projects`.`id` AS t1_r0, `projects`.`name` AS t1_r1, `projects`.`description` AS t1_r2, `projects`.`homepage` AS t1_r3, `projects`.`is_public` AS t1_r4, `projects`.`parent_id` AS t1_r5, `projects`.`created_on` AS t1_r6, `projects`.`updated_on` AS t1_r7, `projects`.`identifier` AS t1_r8, `projects`.`status` AS t1_r9, `projects`.`lft` AS t1_r10, `projects`.`rgt` AS t1_r11, `issue_statuses`.`id` AS t2_r0, `issue_statuses`.`name` AS t2_r1, `issue_statuses`.`is_closed` AS t2_r2, `issue_statuses`.`is_default` AS t2_r3, `issue_statuses`.`position` AS t2_r4, `issue_statuses`.`default_done_ratio` AS t2_r5, `trackers`.`id` AS t3_r0, `trackers`.`name` AS t3_r1, `trackers`.`is_in_chlog` AS t3_r2, `trackers`.`position` AS t3_r3, `trackers`.`is_in_roadmap` AS t3_r4, `enumerations`.`id` AS t4_r0, `enumerations`.`name` AS t4_r1, `enumerations`.`position` AS t4_r2, `enumerations`.`is_default` AS t4_r3, `enumerations`.`type` AS t4_r4, `enumerations`.`active` AS t4_r5, `enumerations`.`project_id` AS t4_r6, `enumerations`.`parent_id` AS t4_r7 FROM `issues` LEFT OUTER JOIN `projects` ON `projects`.`id` = `issues`.`project_id` LEFT OUTER JOIN `issue_statuses` ON `issue_statuses`.`id` = `issues`.`status_id` LEFT OUTER JOIN `trackers` ON `trackers`.`id` = `issues`.`tracker_id` LEFT OUTER JOIN `enumerations` ON `enumerations`.`id` = `issues`.`priority_id` AND `enumerations`.`type` IN ('IssuePriority') WHERE `issues`.`assigned_to_id` IN (252, 10, 62, 119) AND (projects.status=1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) AND (issue_statuses.is_closed = 0) ORDER BY enumerations.position DESC, issues.updated_on DESC LIMIT 10
  Rendered issues/_list_simple.html.erb (1.0ms)
  Token Load (0.9ms)  SELECT `tokens`.* FROM `tokens` WHERE `tokens`.`user_id` = 252 AND (action='feeds') LIMIT 1
  Rendered my/blocks/_issuesassignedtome.html.erb (233.1ms)
   (0.7ms)  SELECT COUNT(DISTINCT `issues`.`id`) FROM `issues` LEFT OUTER JOIN `projects` ON `projects`.`id` = `issues`.`project_id` WHERE `issues`.`author_id` = 252 AND (projects.status=1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking'))
  SQL (1.2ms)  SELECT `issues`.`id` AS t0_r0, `issues`.`tracker_id` AS t0_r1, `issues`.`project_id` AS t0_r2, `issues`.`subject` AS t0_r3, `issues`.`description` AS t0_r4, `issues`.`due_date` AS t0_r5, `issues`.`category_id` AS t0_r6, `issues`.`status_id` AS t0_r7, `issues`.`assigned_to_id` AS t0_r8, `issues`.`priority_id` AS t0_r9, `issues`.`fixed_version_id` AS t0_r10, `issues`.`author_id` AS t0_r11, `issues`.`lock_version` AS t0_r12, `issues`.`created_on` AS t0_r13, `issues`.`updated_on` AS t0_r14, `issues`.`start_date` AS t0_r15, `issues`.`done_ratio` AS t0_r16, `issues`.`estimated_hours` AS t0_r17, `issues`.`parent_id` AS t0_r18, `issues`.`root_id` AS t0_r19, `issues`.`lft` AS t0_r20, `issues`.`rgt` AS t0_r21, `issues`.`position` AS t0_r22, `issues`.`remaining_hours` AS t0_r23, `issues`.`is_private` AS t0_r24, `issues`.`story_points` AS t0_r25, `projects`.`id` AS t1_r0, `projects`.`name` AS t1_r1, `projects`.`description` AS t1_r2, `projects`.`homepage` AS t1_r3, `projects`.`is_public` AS t1_r4, `projects`.`parent_id` AS t1_r5, `projects`.`created_on` AS t1_r6, `projects`.`updated_on` AS t1_r7, `projects`.`identifier` AS t1_r8, `projects`.`status` AS t1_r9, `projects`.`lft` AS t1_r10, `projects`.`rgt` AS t1_r11, `issue_statuses`.`id` AS t2_r0, `issue_statuses`.`name` AS t2_r1, `issue_statuses`.`is_closed` AS t2_r2, `issue_statuses`.`is_default` AS t2_r3, `issue_statuses`.`position` AS t2_r4, `issue_statuses`.`default_done_ratio` AS t2_r5, `trackers`.`id` AS t3_r0, `trackers`.`name` AS t3_r1, `trackers`.`is_in_chlog` AS t3_r2, `trackers`.`position` AS t3_r3, `trackers`.`is_in_roadmap` AS t3_r4 FROM `issues` LEFT OUTER JOIN `projects` ON `projects`.`id` = `issues`.`project_id` LEFT OUTER JOIN `issue_statuses` ON `issue_statuses`.`id` = `issues`.`status_id` LEFT OUTER JOIN `trackers` ON `trackers`.`id` = `issues`.`tracker_id` WHERE `issues`.`author_id` = 252 AND (projects.status=1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking')) ORDER BY issues.updated_on DESC LIMIT 10
  Rendered issues/_list_simple.html.erb (0.2ms)
  Rendered my/blocks/_issuesreportedbyme.html.erb (11.5ms)
  Setting Load (0.4ms)  SELECT `settings`.* FROM `settings` WHERE `settings`.`name` = 'ui_theme' LIMIT 1
  Rendered my/page.html.erb within layouts/base (8081.0ms)
  Setting Load (0.5ms)  SELECT `settings`.* FROM `settings` WHERE `settings`.`name` = 'app_title' LIMIT 1
  Rendered plugins/redmine_code_review/app/views/code_review/_html_header.html.erb (0.8ms)
  Setting Load (0.5ms)  SELECT `settings`.* FROM `settings` WHERE `settings`.`name` = 'login_required' LIMIT 1
  Tracker Load (0.3ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
  IssuePriority Load (0.5ms)  SELECT `enumerations`.* FROM `enumerations` WHERE `enumerations`.`type` IN ('IssuePriority') AND `enumerations`.`is_default` = 1 ORDER BY enumerations.position ASC LIMIT 1
   (0.4ms)  select version from schema_migrations where version like '%-redmine_backlogs'
  Rendered plugins/redmine_backlogs/app/views/hooks/_rb_include_scripts.html.erb (5.1ms)
  SQL (7.8ms)  SELECT `members`.`id` AS t0_r0, `members`.`user_id` AS t0_r1, `members`.`project_id` AS t0_r2, `members`.`created_on` AS t0_r3, `members`.`mail_notification` AS t0_r4, `projects`.`id` AS t1_r0, `projects`.`name` AS t1_r1, `projects`.`description` AS t1_r2, `projects`.`homepage` AS t1_r3, `projects`.`is_public` AS t1_r4, `projects`.`parent_id` AS t1_r5, `projects`.`created_on` AS t1_r6, `projects`.`updated_on` AS t1_r7, `projects`.`identifier` AS t1_r8, `projects`.`status` AS t1_r9, `projects`.`lft` AS t1_r10, `projects`.`rgt` AS t1_r11, `roles`.`id` AS t2_r0, `roles`.`name` AS t2_r1, `roles`.`position` AS t2_r2, `roles`.`assignable` AS t2_r3, `roles`.`builtin` AS t2_r4, `roles`.`permissions` AS t2_r5, `roles`.`issues_visibility` AS t2_r6 FROM `members` LEFT OUTER JOIN `projects` ON `projects`.`id` = `members`.`project_id` LEFT OUTER JOIN `member_roles` ON `member_roles`.`member_id` = `members`.`id` LEFT OUTER JOIN `roles` ON `roles`.`id` = `member_roles`.`role_id` WHERE `members`.`user_id` = 252 AND (projects.status=1) ORDER BY projects.name
  CACHE (0.0ms)  SELECT `trackers`.* FROM `trackers` WHERE `trackers`.`id` IN (1, 2)
  CACHE (0.0ms)  SELECT `enumerations`.* FROM `enumerations` WHERE `enumerations`.`type` IN ('IssuePriority') AND `enumerations`.`is_default` = 1 ORDER BY enumerations.position ASC LIMIT 1
   (0.4ms)  select version from schema_migrations where version like '%-redmine_backlogs'
  Rendered plugins/redmine_code_review/app/views/code_review/_body_bottom.html.erb (1.3ms)
Completed 200 OK in 8968ms (Views: 8508.7ms | ActiveRecord: 46.5ms)
Connecting to database specified by database.yml
Creating scope :active. Overwriting existing method User.active.
Creating scope :open. Overwriting existing method Version.open.
DEPRECATION WARNING: The InstanceMethods module inside ActiveSupport::Concern will be no longer included automatically. Please define instance methods directly in CollectiveIdea::Acts::NestedSet::Model instead. (called from include at /opt/redmine-2.0/lib/plugins/awesome_nested_set/lib/awesome_nested_set/awesome_nested_set.rb:58)
DEPRECATION WARNING: The InstanceMethods module inside ActiveSupport::Concern will be no longer included automatically. Please define instance methods directly in CollectiveIdea::Acts::NestedSet::Model instead. (called from include at /opt/redmine-2.0/lib/plugins/awesome_nested_set/lib/awesome_nested_set/awesome_nested_set.rb:58)
Creating scope :open. Overwriting existing method Issue.open.
OpenIdAuthentication.store is nil. Using in-memory store.
Backlogs printable cards: problem loading labels: undefined method `merge' for #<BacklogsPrintableCards::CardPageLayout:0x00000003bfd8f0>

If this data is insufficient and you need a more complete log let me know.

#5 Updated by Jean-Philippe Lang over 9 years ago

  • Resolution set to Cant reproduce

This logs combines several requests, it's unusable for debugging purpose. And I see a lot of plugin stuff, please try without plugins first. FYI, updating issues via the REST API is part of the of tests suite.

#6 Updated by Adrian Wilkins over 9 years ago

I'm also seeing this in conjunction with the Redmine plugin for Mylyn

In my case, the "Estimated time" field is set, but the notes are not.

I think the relevant log segment is as follows :

Started GET "/request/mylyn/token?key=f965c537cec5c75843a73588cfa57d07db54291a" for 10.149.126.35 at Mon Mar 11 17:25:15 +0000 2013
Processing by MylynConnector::InformationController#token as TEXT
  Parameters: {"key"=>"f965c537cec5c75843a73588cfa57d07db54291a"}
  Current user: adwi2 (id=54)
Completed 200 OK in 10ms (Views: 0.4ms | ActiveRecord: 0.8ms)
Started PUT "/request/issues/2433.xml?key=f965c537cec5c75843a73588cfa57d07db54291a" for 10.149.126.35 at Mon Mar 11 17:25:15 +0000 2013
Processing by IssuesController#update as XML
  Parameters: {"issue"=>{"parent_issue_id"=>"", "start_date"=>"", "subject"=>"Test Mylyn", "custom_field_values"=>{"18"=>"", "13"=>"", "12"=>""}, "project_id"=>"1", "watcher_user_ids"=>nil, "fixed_version_id"=>"", "due_date"=>"", "status_id"=>"9", "priority_id"=>"5", "tracker_id"=>"10", "done_ratio"=>"0", "assigned_to_id"=>"54", "estimated_hours"=>"0.0", "description"=>"Tweet tweet.", "category_id"=>""}, "notes"=>"Poot poot.", "id"=>"2433", "key"=>"f965c537cec5c75843a73588cfa57d07db54291a"}
WARNING: Can't verify CSRF token authenticity
  Current user: adwi2 (id=54)
  Rendered mailer/_issue.text.erb (7.8ms)
  Rendered mailer/issue_edit.text.erb within layouts/mailer (10.7ms)
  Rendered mailer/_issue.html.erb (5.1ms)
  Rendered mailer/issue_edit.html.erb within layouts/mailer (7.8ms)
  Rendered text template (0.0ms)
Completed 200 OK in 1002ms (Views: 2.4ms | ActiveRecord: 48.7ms)

#7 Updated by Adrian Wilkins over 9 years ago

Here's just the parameters from the log above, followed by one from manually updating an issue via IRB / ActiveResource. I've indented the parameters.

Processing by IssuesController#update as XML
  Parameters: 
{
    "issue"=>
        {
          "parent_issue_id"=>"" 
        , "start_date"=>"" 
        , "subject"=>"Test Mylyn" 
        , "custom_field_values"=>{"18"=>"", "13"=>"", "12"=>""}
        , "project_id"=>"1" 
        , "watcher_user_ids"=>nil
        , "fixed_version_id"=>"" 
        , "due_date"=>"" 
        , "status_id"=>"9" 
        , "priority_id"=>"5" 
        , "tracker_id"=>"10" 
        , "done_ratio"=>"0" 
        , "assigned_to_id"=>"54" 
        , "estimated_hours"=>"0.0" 
        , "description"=>"Tweet tweet." 
        , "category_id"=>"" 
        }
    , "notes"=>"Poot poot." 
    , "id"=>"2433" 
    , "key"=>"f965c537cec5c75843a73588cfa57d07db54291a" 
}

And the ActiveResource one..

Processing by IssuesController#update as XML
  Parameters: 
{
    "issue"=>
        {
        "tracker"=>
            {"id"=>"10", "name"=>"Request"}
        , "created_on"=>"2013-03-11T16:14:15Z" 
        , "priority"=>{"id"=>"5", "name"=>"P3 (Medium)"}
        , "description"=>"Testing mylyn integration" 
        , "id"=>"2436" 
        , "notes"=>"Testing from irb" 
        , "due_date"=>nil
        , "updated_on"=>"2013-03-11T16:19:11Z" 
        , "author"=>{"id"=>"54", "name"=>"Wilkins, Adrian"}
        , "start_date"=>nil
        , "assigned_to"=>{"id"=>"54", "name"=>"Wilkins, Adrian"}
        , "project"=>{"id"=>"1", "name"=>"Redmine Meta Project"}
        , "spent_hours"=>"0.0" 
        , "custom_fields"=>
            [
              {"id"=>"12", "name"=>"Service", "value"=>nil}
            , {"id"=>"13", "name"=>"Customer", "value"=>nil}
            , {"id"=>"18", "name"=>"Customer Portfolio", "value"=>nil}
            ]
        , "status"=>{"id"=>"9", "name"=>"Assigned"}
        , "subject"=>"Test Mylyn interaction" 
        , "done_ratio"=>"0" 
        , "estimated_hours"=>"0.0" 
        }
    , "id"=>"2436" 
}

It looks like the notes are being passed as a a parameter outside the issue by the Mylyn API call, whereas ActiveResource passes it as a field on the issue object.

ActiveResource works, the Mylyn call does not.

I suspect from this that the REST API previously accepted "notes" as a parameter on the main update call, rather than as a field on the issue object, since the same client worked properly before upgrading from a 1.4.x series server to 2.2.x

Potential suggestions :

  • Patch to accept the old behaviour OR
  • Return an error to calls that include a notes parameter at the top level of the call.
    • This at least enables broken implementations to be aware that they are broken.

Looking at the logs above on the original issue submitters server.. the parameters list is only the ID. No wonder his client isn't updating the issue.

#8 Updated by Adrian Wilkins over 9 years ago

Have patched my local copy of the Mylyn plugin to send notes as a field on the issue object rather than as a separate field. Success!

Not sure there is an active maintainer of it but will do best to feed this upstream.

I guess people implementing clients might need to be aware of what seems to be a change in the REST API behaviour (if not it's specification).

Also available in: Atom PDF