"Create Issue" leads to HTTP 404 error, HTTP address valid

[realtimecarsten]

redmine runs on the same host as the Outlook client.
I access redmine via "http://127.0.0.1:7777", this has never caused problems.
I installed the Outlook Issue Tracker, installation looks fine (see attached image 01).

However, when trying to create an issue, I get an error 404 (see attached image 02)

Directly accessing the address in the browser works without problems (see attached image 03).

Any idea what could be the cause of this?

Environment:
Redmine version 2.6.1.stable
Ruby version 1.9.3-p545 (2014-02-24) [i386-mingw32]
Rails version 3.2.21
Environment production
Database adapter SQLite
SCM:
Git 1.9.4
Filesystem
Redmine plugins:
redmine_better_gantt_chart 0.9.0
redmine_checklists 3.0.2
redmine_mylyn_connector 2.8.2.stable

Outlook; 14.0.7015.1000 (32bit)

Win7, Version 6.1 Build 7601 SP 1

[wolfgangimig]

This error might occur, if the Addin sends an invalid ID for the selected project, tracker, priority, or assignee. Are the selected issue options suitable to the project? When selecting a project, the Addin must update the items in the other combo boxes. This might fail due to an error which is not reported.
The browser request succeeds, because it's a HTTP GET request. In order to create an issue, a POST has to be sent.
More information about what happens should be printed on stdout and into the log file, after you enabled logging: please go through this steps.

[realtimecarsten]

Ok, enabled logging. And started redmine from command line, that gives me a lot more messages. No more time today or tomorrow, but I will look further into this - seems to be a problem with formats missing in my redmine installation. Thanks for your help, I will keep you informed if I succeed to get this running.

[wolfgangimig]

timeout

[eloops]

I am having the same issue.

Redmine version 2.6.5.stable
ruby 2.1.5p273 (2014-11-13 revision 48405) [armv6l-linux-eabihf]
Rails version 3.2.21
Environment production
Database adapter postgresql (active-record) 4.2.1
SCM:
Git 1.9.4
Filesystem

Redmine plugins:
(none, I have disabled them)

Outlook; 16.0.4027.1008 (32bit)

Win8.1 Pro 64-bit, Version 6.3 Build 9600

I have tried debugging it but I don't understand what is going on here. Your link to enable logging ('backstage' ?) no longer works.

I have tried to follow your instructions for installing, it doesn't seem to have created the 'itol-configuration' project as specified. I've tried to log in as 'admin' user and create a new issue but it continues to throw the same error as above.
I've also tried uninstalled / rebooting / reinstalling however the issue tracker is recording the options somewhere, unsure where this is located.

Any help would be appreciated.

[wolfgangimig]

Outook backstage view can be found here.
There should be an entry "Issue Tracker" in the left column. Clicking this entry shows this dialog:

Enter a Log-file and select level INFO. Then click Save.
Paste the log file here, at least the part where the 404 error occurs and 10 lines before and after.
Did you installed ITOL version 1.4?

[eloops]

2015-06-03 08:51:49,216 INFO com.wilutions.itol.db.HttpClient send GET http://redmine:3000/projects/1/versions.json #-1
2015-06-03 08:51:50,538 INFO com.wilutions.itol.db.HttpClient send 200 #31
2015-06-03 08:51:50,579 INFO com.wilutions.itol.db.HttpClient send GET http://redmine:3000/projects/1/memberships.json?offset=0&limit=100 #-1
2015-06-03 08:51:51,288 INFO com.wilutions.itol.db.HttpClient send 200 #314
2015-06-03 08:51:51,291 INFO jdk.nashorn.internal.scripts.Script$Recompilation$114$14282A$IssueServiceImpl readProjectMembers member: project.id=1, user.id=5, .name=Stephen Poole
2015-06-03 08:51:51,292 INFO jdk.nashorn.internal.scripts.Script$Recompilation$114$14282A$IssueServiceImpl readProjectMembers member: project.id=1, user.id=1, .name=Redmine Admin
2015-06-03 08:51:51,292 INFO com.wilutions.itol.db.HttpClient send GET http://redmine:3000/projects/1/memberships.json?offset=2&limit=100 #-1
2015-06-03 08:51:51,763 INFO com.wilutions.itol.db.HttpClient send 200 #57
2015-06-03 08:52:15,925 INFO com.wilutions.itol.db.HttpClient send POST http://redmine:3000/uploads.json #24576
2015-06-03 08:52:17,635 INFO com.wilutions.itol.db.HttpClient send 201 #57
2015-06-03 08:52:17,679 INFO com.wilutions.itol.db.HttpClient send POST http://redmine:3000/issues.json #-1
2015-06-03 08:52:17,919 INFO com.wilutions.itol.db.HttpClient send send failed, exception=java.io.FileNotFoundException: http://redmine:3000/issues.json
2015-06-03 08:52:17,923 SEVE com.wilutions.itol.IssueTaskPane lambda$13 Failed to update issue
file:/C:/Users/Stephen/AppData/Local/Issue%20Tracker%20for%20Microsoft%20Outlook%2032bit/app/IssueServiceImpl.js:243:3 java.io.IOException: HTTP Status 404, http://redmine:3000/issues.json
  at jdk.nashorn.internal.runtime.ECMAException.create(ECMAException.java:113)
  at jdk.nashorn.internal.scripts.Script$Recompilation$92$7049AAAAA$IssueServiceImpl.send(file:/C:/Users/Stephen/AppData/Local/Issue%20Tracker%20for%20Microsoft%20Outlook%2032bit/app/IssueServiceImpl.js:243)
  at jdk.nashorn.internal.scripts.Script$Recompilation$124$8040AAA$IssueServiceImpl.post(file:/C:/Users/Stephen/AppData/Local/Issue%20Tracker%20for%20Microsoft%20Outlook%2032bit/app/IssueServiceImpl.js:262)
  at jdk.nashorn.internal.scripts.Script$Recompilation$123$15276AA$IssueServiceImpl.writeIssue(file:/C:/Users/Stephen/AppData/Local/Issue%20Tracker%20for%20Microsoft%20Outlook%2032bit/app/IssueServiceImpl.js:531)
  at jdk.nashorn.internal.scripts.Script$Recompilation$86$41495AAA$IssueServiceImpl.updateIssue(file:/C:/Users/Stephen/AppData/Local/Issue%20Tracker%20for%20Microsoft%20Outlook%2032bit/app/IssueServiceImpl.js:1377)
  at com.wilutions.itol.db.IssueService$$NashornJavaAdapter.updateIssue(Unknown Source)
  at com.wilutions.itol.IssueTaskPane.updateIssueChangedMembers(IssueTaskPane.java:1185)
  at com.wilutions.itol.IssueTaskPane.lambda$13(IssueTaskPane.java:1132)
  at com.wilutions.itol.IssueTaskPane$$Lambda$531/4087807.run(Unknown Source)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)
  at com.wilutions.com.BackgTask$1$1.run(BackgTask.java:80)
Caused by: java.io.IOException: HTTP Status 404, http://redmine:3000/issues.json
  ... 12 more

Yes, I installed v1.4. I didn't realise that screen was officially called backstage view.

[wolfgangimig]

Please check the points from my first answer in this thread:

This error might occur, if the Addin sends an invalid ID...

Further information might be found in Redmine's log file.

[eloops]

Where are the configuration options saved? I tried clearing out my temp files & cleaning up the registry, but when I reinstalled it the options input were still there.

[eloops]

I have tried:

• Creating a new issue (results in above error)
• Appending to an existing issue - details load correctly and appears to update but checking the issue in redmine doesn't show any update
• Changing the webserver from puma to thin - this at least allowed me to see the request being made. (It still made no sense to me)
• I changed the host (originally an rpi) to a vm w/2gb memory & 2 CPU's, as I thought it might be timing out on the rpi.
• Have created a new, blank database with default data loaded as per Redmine install instructions
• Tested with another copy of Office 2013 (on different PC) to same server

In all these scenarios the error remains the same - 404 file not found. I have tried to understand the IssueServiceImpl.js as written however I can't see anything that would cause it to trip up Redmine.

The 'readme.txt' states in 3 that the 'admin' user should be set up first in order for the 'itol-configuration' project to be created initially. ** This project has never been created **. Should I create this project manually? Is there a format to follow in creating this project?

I have also examined the logs for redmine, puma (and now thin). They all are mostly uninformative. Puma was throwing an error around 'httpparser error' or somesuch, I can get an exact log of it later when I have another look at it.

[wolfgangimig]

I have downloaded the VM from Bitnami that includes Redmine 2.6.5 - the same version as yours - in order to check whether ITOL can work with this version. I can create issues and the configuration project is also created.

Please set the logging level for ITOL to DEBUG and restart Outlook.
In the log file, you can watch the creation of the configuration project, see lines after "readOrUpdateConfigurationProject". The procedure tries to read the project first - which results in an error as expected, if it does not exist. Then, the project is updated or created - which fails as expected, if you are not an admin.

An issue is created starting with "writeIssue(". All properties of the issue to be created are printed into the log:

...
  "issue": {
    "id": "",        
    "project_id": 2,
    "tracker_id": 1,
    "status_id": 1,
    "priority_id": 2, 

Check whether the given IDs for project_id, ... are valid.

Since neither the configuration project nor an issue is created: is there anything in your environment that blocks POST or PUT requests? e.g. something like this: http://stackoverflow.com/questions/24691560/nginx-redirects-post-requests-to-get-request

Your questions:

Where are the configuration options saved?
They are inserted into the Windows registry: HKEY_CURRENT_USER\Software\WILUTIONS\Issue Tracker for Microsoft Outlook and Redmine\Config

Should I create this project manually? Is there a format to follow in creating this project?
This project contains encrypted information. You cannot create it manually.

[eloops]

Thanks for your response and your patience! I will have another look at this today or later tonight when I get a chance.
I suspect it may have something do with puma (and thin) not being able to handle chunked encoding properly, see links:
puma/puma#620
http://atnan.com/blog/2008/08/08/transfer-encoding-chunked-or-chunky-http/

That second link mentions setting up Apache2 as a proxy, I will just go ahead and set up Apache2 as the web server and see if it handles things differently (I note that the Bitnami VM you downloaded uses Apache).

I will also check what id's are being requested and report back too.

UPDATE: Have been testing this. When I post the json using

curl -v -H "Content-Type: application/json" -X post --data "@file.json -H "X-Redmine-API-Key:[key]" http://url/issues.json

It works as expected. Same with the itol-coniguration project creation. Am not sure why this is.

I still haven't had a chance to test out apache2, I will try this out next. In other setups (that involve passing the requests through to something like nginx) maybe something is done that makes it work?

The debug log from redmine looks like:

Processing by IssuesController#create as JSON
   (0.9ms)  SELECT MAX("settings"."updated_on") AS max_id FROM "settings"
  Setting Load (1.0ms)  SELECT "settings".* FROM "settings" WHERE "settings"."name" = 'rest_api_enabled' LIMIT 1
  Token Load (0.9ms)  SELECT "tokens".* FROM "tokens" WHERE "tokens"."action" = 'api' AND "tokens"."value" = '32209f16de14ceb8d3155874d2a6e820cbd9d1f6' LIMIT 1
  User Load (1.1ms)  SELECT "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."id" = 1 LIMIT 1
  Current user: admin (id=1)
  Setting Load (0.8ms)  SELECT "settings".* FROM "settings" WHERE "settings"."name" = 'force_default_language_for_loggedin' LIMIT 1
  Setting Load (0.9ms)  SELECT "settings".* FROM "settings" WHERE "settings"."name" = 'force_default_language_for_anonymous' LIMIT 1
  Setting Load (0.7ms)  SELECT "settings".* FROM "settings" WHERE "settings"."name" = 'default_language' LIMIT 1
Filter chain halted as :find_project rendered or redirected
Completed 404 Not Found in 110.3ms (ActiveRecord: 16.2ms)

This issue deals with it, but there's nothing there other than the JSON isn't parsed correctly. I think it's definitely the webserver (not passing through the JSON correctly/fully).

Here's the JSON for reference:

{"issue":{"id":"","project_id":2,"tracker_id":1,"status_id":1,"priority_id":2,"subject":"test","description":"This is a test\n\n \n","notes":"","assigned_to_id":"","category_id":"","fixed_version_id":"","start_date":"2015-06-05","due_date":"","estimated_hours":"","done_ratio":"0","uploads":[{"token":"6.037ead9cc48f1c348bab157d5f988e7d","filename":"C:\\Users\\Stephen\\AppData\\Local\\Temp\\itol7399253363337815883.tmp\\1433485788120\\test.msg","content_type":"application/vnd.ms-outlook"}]}}

[eloops]

I think I have found the problem for this. As expected, with Apache2 as the web server all requests worked fine from within Outlook.
When I put nginx in front of the puma app server it started throwing '411' errors requesting the 'Content-Length' header.

I altered the 'IssueServiceImpl.js' file with a couple quick changes to add in the content-length header to the POST and PUT requests:

function lengthInUtf8Bytes(str) {
  var m = encodeURIComponent(str).match(/%[89ABab]/g);
  return str.length + (m ? m.length : 0);
}

post : function(params, content, progressCallback) {
  var headers = [ "Content-Type: application/json" ];
  var jsonStr = JSON.stringify(content);
  var jsonLength = lengthInUtf8Bytes(jsonStr);
  headers.push("Content-Length: " + jsonLength);

Same for PUT.
I tested this against puma, thin and unicorn. All worked okay, including issue creation & updates, including uploading attachments (though that already adds the content-length header). Curl automatically adds the content-length header anyway.

It seems (happy to be corrected) that when connecting directly with these app servers that they are not handling the Transfer-Encoding: chunked header correctly, and are still waiting on the Content-Length header to receive the JSON data. So clearly not an issue with ITOL!

Thanks again.

[wolfgangimig]

Super! Many thanks for your investigation.

Usually,Java's HttpURLConnection class, which is used in my wrapper JHttpClient, sets the Content-Length header correctly. But I explicitly set chunked encoding, if the contentLength parameter is -1. I will change this in the next version for contents of type String.

Kind regards,
Wolfgang