Redmine

Hi,

Here's a log from my app:

2012-04-11 14:48:20.819 Eon[55805:907] Selecting project <FCIntegrationProject: 0x7fb0806e6c20> - 1 - Load VDF xml (service layer) into code of <FCRedmineIntegration: 0x7fb0806e61f0> integration
2012-04-11 14:48:26.788 Eon[55805:907] -[FCRedmineIntegration postTimeForProject:]:148: Preparing to post.
2012-04-11 14:48:26.789 Eon[55805:907] FCRedminePosterTemplate: Created body {"task_id":"1","hours":"1.00","comments":"Re-structuring parsing for instances where there is no single root"}.
2012-04-11 14:48:26.789 Eon[55805:907] FCRedminePoster: Posting to URL http://localhost:3000/time_entries
2012-04-11 14:48:26.827 Eon[55805:907] FCRedminePoster: Posted with status code 406.
2012-04-11 14:48:26.827 Eon[55805:907] FCRedminePoster: Received data ' '.

and the Redmine log:

Processing TimelogController#create (for 127.0.0.1 at 2012-04-11 14:48:26) [POST]
Parameters: {"comments"=>"Re-structuring parsing for instances where there is no single root", "hours"=>"1.00", "action"=>"create", "controller"=>"timelog", "task_id"=>"1"}
Filter chain halted as [:find_project] rendered_or_redirected.
Completed in 5ms (View: 0, DB: 1) | 406 Not Acceptable [http://localhost/time_entries]

The previous 404 error was with XML. I will post the server log for that as soon as I get a permission to do so.

Thanks for looking into this!

Krystof

More logs from the same error

xx.xx.xx.xx - - [11/Apr/2012:16:04:25 +0200] "POST /time_entries HTTP/1.1" 406 756 "-" "Eon/363 CFNetwork/520.3.2 Darwin/11.3.0 (x86_64) (MacBookPro6%2C2)" 

Processing TimelogController#create (for xx.xx.xx.xx at 2012-04-11 16:04:24) [POST]
  Parameters: {"controller"=>"timelog", "comments"=>"test comment", "action"=>"create", "hours"=>"0.01", "task_id"=>"729"}
  SQL (0.1ms)   SELECT max(`settings`.updated_on) AS max_updated_on FROM `settings` 
  User Load (0.1ms)   SELECT * FROM `users` WHERE (BINARY login = '<hash>') AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) LIMIT 1
  User Load (0.1ms)   SELECT * FROM `users` WHERE (BINARY LOWER(login) = '<hash>') AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) LIMIT 1
  AuthSource Load (11.8ms)   SELECT * FROM `auth_sources` WHERE (onthefly_register=1) 
  Token Load (0.1ms)   SELECT * FROM `tokens` WHERE (`tokens`.`value` = '<hash>' AND `tokens`.`action` = 'api') LIMIT 1
  User Load (0.1ms)   SELECT * FROM `users` WHERE (`users`.`id` = 1) AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) 
Filter chain halted as [:find_project] rendered_or_redirected.
Completed in 137ms (View: 1, DB: 12) | 406 Not Acceptable [https://url/time_entries]]

Do you provide Rest API authentication token?

Hi Etienne and Jean-Philippe,

these logs are when using to post JSON using the REST API. Here's a log for XML that returns 404. The request does have valid XML content/accept header values, the API key is set as user name, having XXX passed as password. Other API calls work fine (at least that I've tried - getting project/issue lists). Also the weird thing is that the comments field in the XML gets omitted (you can see the field in the posted XML - log from the application; however, in the Redmine log, it's getting nil).

2012-04-10 10:19:05.984 Eon[6368:907] -[FCRedmineIntegration postTimeForProject:]:147: Preparing to post.
2012-04-10 10:19:05.985 Eon[6368:907] FCRedminePosterTemplate: Created body <time_entry><task_id>700</task_id><hours>0.59</hours><comments>....</comments></time_entry>.
2012-04-10 10:19:05.985 Eon[6368:907] FCRedminePoster: Posting to URL https://projekt.fairweb.dk/time_entries.xml.
2012-04-10 10:19:05.992 Eon[6368:907] should
2012-04-10 10:19:06.047 Eon[6368:907] resp
2012-04-10 10:19:06.047 Eon[6368:907] data
2012-04-10 10:19:06.048 Eon[6368:907] finish
2012-04-10 10:19:06.988 Eon[6368:907] FCRedminePoster: Posted with status code 404.
2012-04-10 10:19:06.989 Eon[6368:907] FCRedminePoster: Received data ' '.

Processing TimelogController#create to xml (for 46.xx.xx.xx at 2012-04-10 11:21:17) [POST]
  Parameters: {"format"=>"xml", "controller"=>"timelog", "action"=>"create", "time_entry"=>{"comments"=>nil, "hours"=>"0.59", "task_id"=>"700"}}
  SQL (0.1ms)   SELECT max(`settings`.updated_on) AS max_updated_on FROM `settings` 
  User Load (0.1ms)   SELECT * FROM `users` WHERE (BINARY login = '<HASH>') AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) LIMIT 1
  User Load (0.1ms)   SELECT * FROM `users` WHERE (BINARY LOWER(login) = '<HASH>') AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) LIMIT 1
  AuthSource Load (0.1ms)   SELECT * FROM `auth_sources` WHERE (onthefly_register=1)
  Token Load (0.1ms)   SELECT * FROM `tokens` WHERE (`tokens`.`value` = '<HASH>' AND `tokens`.`action` = 'api') LIMIT 1
  User Load (0.1ms)   SELECT * FROM `users` WHERE (`users`.`id` = 1) AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) )
Filter chain halted as [:find_project] rendered_or_redirected.
Completed in 6ms (View: 0, DB: 0) | 404 Not Found [https://<domain>/time_entries.xml]

Thanks!

Krystof

task_id is not a legal parameter, you should use issue_id.

See Rest_TimeEntries for a list of legal parameters.

Update with issue_id (now error 500):

Redmine log:

Processing TimelogController#create (for xx.xx.xx.xx at 2012-04-12 13:51:19) [POST]
  Parameters: {"controller"=>"timelog", "action"=>"create", "time_entry"=>{"comments"=>"Testing version 367", "hours"=>"0.05", "issue_id"=>"729"}}
  SQL (0.1ms)   SELECT max(`settings`.updated_on) AS max_updated_on FROM `settings` 
  User Load (0.1ms)   SELECT * FROM `users` WHERE (BINARY login = 'hash') AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) LIMIT 1
  User Load (0.1ms)   SELECT * FROM `users` WHERE (BINARY LOWER(login) = 'hash') AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) LIMIT 1
  AuthSource Load (0.1ms)   SELECT * FROM `auth_sources` WHERE (onthefly_register=1) 
  Token Load (0.1ms)   SELECT * FROM `tokens` WHERE (`tokens`.`value` = 'hash' AND `tokens`.`action` = 'api') LIMIT 1
  User Load (0.1ms)   SELECT * FROM `users` WHERE (`users`.`id` = 1) AND ( (`users`.`type` = 'User' OR `users`.`type` = 'AnonymousUser' ) ) 
  Issue Load (0.1ms)   SELECT * FROM `issues` WHERE (`issues`.`id` = 729) 
  Project Load (0.1ms)   SELECT * FROM `projects` WHERE (`projects`.`id` = 19) 
  EnabledModule Load (0.1ms)   SELECT name FROM `enabled_modules` WHERE (`enabled_modules`.project_id = 19) 
  UserPreference Load (0.1ms)   SELECT * FROM `user_preferences` WHERE (`user_preferences`.user_id = 1) LIMIT 1
  TimeEntryActivity Load (0.1ms)   SELECT * FROM `enumerations` WHERE (`enumerations`.`is_default` = 1) AND ( (`enumerations`.`type` = 'TimeEntryActivity' ) ) ORDER BY enumerations.position ASC LIMIT 1
  SQL (0.1ms)   BEGIN
  CustomField Load (0.1ms)   SELECT * FROM `custom_fields` WHERE (type = 'TimeEntryCustomField') ORDER BY position
  TimeEntry Create (0.3ms)   INSERT INTO `time_entries` (`project_id`, `comments`, `spent_on`, `user_id`, `tmonth`, `updated_on`, `hours`, `created_on`, `activity_id`, `issue_id`, `tyear`, `tweek`) VALUES(19, 'Testing version 367', '2012-04-12', 1, 4, '2012-04-12 13:51:19', 0.05, '2012-04-12 13:51:19', 9, 729, 2012, 15)
  CustomValue Load Including Associations (0.7ms)   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 FROM `custom_values` LEFT OUTER JOIN `custom_fields` ON `custom_fields`.id = `custom_values`.custom_field_id WHERE (`custom_values`.customized_id = 1261 AND `custom_values`.customized_type = 'TimeEntry') ORDER BY custom_fields.position
  SQL (15.0ms)   COMMIT

ActionView::MissingTemplate (Missing template timelog/show.erb in view path vendor/plugins/redmine_git_hosting/app/views:vendor/plugins/redmine_mylyn_connector/app/views:vendor/plugins/redmine_spent_time/app/views:vendor/plugins/redmine_time_tracker/app/views:app/views):
  app/controllers/application_controller.rb:518:in `default_template'
  app/controllers/timelog_controller.rb:127
  app/controllers/timelog_controller.rb:122:in `create'
....
Rendering /var/www/redmine/public/500.html (500 Internal Server Error)

Looks like a plugin issue, test with no plugins installed?

Hi,

removing the plugins doesn't change anything.

Krystof

Also note that the time entry actually gets created (see the INSERT SQL command in the log), but it still returns 500.

Still think this is a plugin issue, what's your Redmine version?

The bug exists on both 1.3-stable and 1.4-stable and with no plugin installed

Again, I can't reproduce. You're getting a 500 error because you're missing a view that actually exists in Redmine 1.3 and 1.4.

It appears that the OP has had an RTFM issue, see my comment here:

<http://www.redmine.org/boards/2/topics/29054?r=31882#message-31882>

I have fallen into the same trap and it has cost me the better part of a day to find out what the problem is. This was mostly because a) the returned error message was an unhelpful 404 and b) I did not expect at all that the XML/JSON body format for a POST request must be different than the format you receive with a GET request.

More precisely, if the GET request returns <activity name="Whatever" id="9" /> then I would expect that I can specify <activity id="9" /> in the POST request. However, according to the documentation <activity_id>9</activity_id> seems to be required.