Fix 404 error after restarting app

[jgaehring]

In the Android app, after you close the app and restart it, any attempts to sync logs comes up with a 404 error.

In debugging, I'm able to force the app to reroute to the login (window.location = "file:///android_asset/www/index.html#/login"), login successfully, then when I try to sync it works. It seems like an auth issue, but the fact that we're getting a 404 instead of a 403 is weird. Weirder still is that the 404 is a response to requesting the /log endpoint, which we know to work. The tokens and cookies are both the same, whether it succeeds or not. Another weird thing is that prior to the 404, there's a preceding request (also to /log) which comes back as a 301 ("Moved Permanently"), as opposed to the 307 ("Internal Redirect") which we get during a successful sync.

:thinking:

I'll post the request and response headers for both successful and unsuccessful requests below in another comment shortly.

A quick-fix to this issue would just be to tell the app to redirect to the home page if it gets a 404, but I'd rather get to the bottom of why the 404 is being thrown in the first place, b/c it makes no sense. @mstenta, could there be something on the server side that's responsible for this behavior?

[mstenta]

What URL are you testing against? test.farmos.net? I can check the server logs...

[jgaehring]

Successful Sync Attempt

First Request/Response

Request URL: http://test.farmos.net/log Request Method: POST Status Code: 307 Internal Redirect Referrer Policy: no-referrer-when-downgrade

Request Headers

Accept: json Content-Type: application/json Origin: file:// User-Agent: Mozilla/5.0 (Linux; Android 9; Pixel 3 Build/PQ1A.181205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/71.0.3578.99 Mobile Safari/537.36 X-CSRF-Token: ejY3koqA-pWzhd8hyl5qXoUvAOM66rrjzynspE8X9EM

Response Headers

HTTP/1.1 307 Internal Redirect Location: https://test.farmos.net/log Non-Authoritative-Reason: HSTS Access-Control-Allow-Origin: file:// Access-Control-Allow-Credentials: true

Request Payload

{"field_farm_notes":{"format":"farm_format","value":"

\n"},"name":"12/24/2018 - 9:12:54 AM","type":"farm_observation","timestamp":"1545660774","field_farm_images":[]}

Second Request/Response

Request URL: https://test.farmos.net/log Request Method: POST Status Code: 201 Created Remote Address: 34.195.85.140:443 Referrer Policy: no-referrer-when-downgrade

Request Headers

POST /log HTTP/1.1 Host: test.farmos.net Connection: keep-alive Content-Length: 172 Accept: json Origin: null X-CSRF-Token: ejY3koqA-pWzhd8hyl5qXoUvAOM66rrjzynspE8X9EM User-Agent: Mozilla/5.0 (Linux; Android 9; Pixel 3 Build/PQ1A.181205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/71.0.3578.99 Mobile Safari/537.36 Content-Type: application/json Accept-Encoding: gzip, deflate Accept-Language: en-US Cookie: SESS9646fa17283c8d6f6c92f39f1c0e12b4=h6KEB8pWj1DgjUxsfcnHGKFOy34OVpJHdcQqPoIKkVk X-Requested-With: org.farmos.app

Response Headers

HTTP/1.1 201 Created Server: nginx/1.11.10 Date: Wed, 26 Dec 2018 15:32:17 GMT Content-Type: application/json Content-Length: 73 Connection: keep-alive Expires: Sun, 19 Nov 1978 05:00:00 GMT Cache-Control: no-cache, must-revalidate X-Content-Type-Options: nosniff Access-Control-Allow-Origin: http://localhost:8080 Access-Control-Allow-Credentials: true Strict-Transport-Security: max-age=31536000

Request Payload

{"field_farm_notes":{"format":"farm_format","value":"

\n"},"name":"12/24/2018 - 9:12:54 AM","type":"farm_observation","timestamp":"1545660774","field_farm_images":[]}

Unsuccessful Sync Attempt

First Request/Response

Request URL: http://test.farmos.net/log Request Method: POST Status Code: 301 Moved Permanently Remote Address: 34.195.85.140:80 Referrer Policy: no-referrer-when-downgrade

Request Headers

POST /log HTTP/1.1 Host: test.farmos.net Connection: keep-alive Content-Length: 172 Accept: json Origin: file:// X-CSRF-Token: ejY3koqA-pWzhd8hyl5qXoUvAOM66rrjzynspE8X9EM User-Agent: Mozilla/5.0 (Linux; Android 9; Pixel 3 Build/PQ1A.181205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/71.0.3578.99 Mobile Safari/537.36 Content-Type: application/json Accept-Encoding: gzip, deflate Accept-Language: en-US Cookie: SESS9646fa17283c8d6f6c92f39f1c0e12b4=h6KEB8pWj1DgjUxsfcnHGKFOy34OVpJHdcQqPoIKkVk X-Requested-With: org.farmos.app

Response Headers

HTTP/1.1 301 Moved Permanently Server: nginx/1.11.10 Date: Wed, 26 Dec 2018 15:29:54 GMT Content-Type: text/html Content-Length: 186 Connection: keep-alive Location: https://test.farmos.net/log

Request Payload

{"field_farm_notes":{"format":"farm_format","value":"

\n"},"name":"12/24/2018 - 9:12:54 AM","type":"farm_observation","timestamp":"1545660774","field_farm_images":[]}

Second Request/Response

Request URL: https://test.farmos.net/log Request Method: GET Status Code: 404 Not Found Remote Address: 34.195.85.140:443 Referrer Policy: no-referrer-when-downgrade

Request Headers

GET /log HTTP/1.1 Host: test.farmos.net Connection: keep-alive Accept: json X-CSRF-Token: ejY3koqA-pWzhd8hyl5qXoUvAOM66rrjzynspE8X9EM User-Agent: Mozilla/5.0 (Linux; Android 9; Pixel 3 Build/PQ1A.181205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/71.0.3578.99 Mobile Safari/537.36 Accept-Encoding: gzip, deflate Accept-Language: en-US Cookie: SESS9646fa17283c8d6f6c92f39f1c0e12b4=h6KEB8pWj1DgjUxsfcnHGKFOy34OVpJHdcQqPoIKkVk X-Requested-With: org.farmos.app

Response Headers

HTTP/1.1 404 Not Found Server: nginx/1.11.10 Date: Wed, 26 Dec 2018 15:29:54 GMT Content-Type: text/html; charset=utf-8 Transfer-Encoding: chunked Connection: keep-alive Expires: Sun, 19 Nov 1978 05:00:00 GMT Cache-Control: no-cache, must-revalidate X-Content-Type-Options: nosniff Access-Control-Allow-Origin: http://localhost:8080 Access-Control-Allow-Credentials: true Content-Language: en X-Frame-Options: SAMEORIGIN X-Generator: Drupal 7 (http://drupal.org)

[jgaehring]

What URL are you testing against? test.farmos.net? I can check the server logs...

@mstenta , yes, test.farmos.net

[mstenta]

I see the 404s in the logs - all of them are GET requests. The /log endpoint returns 404 on GET, so that is expected behavior. It seems that it's not sending a POST as it should be.

Worth noting: typically if a POST request is sent to a URL, but a redirect occurs, the request will be changed from a POST to a GET, and the data from the POST will not be forwarded along to the new destination. It sounds like this is what's happening?

The question is: why does it work on the first try, but not on later tries?

[jgaehring]

One more thing I've noticed: the 2nd request in an unsuccessful sync is a GET request instead of a POST, and it lacks a payload. I can't help feeling, however, that this is all initiated by that weird 307 redirect that kicks off the second request. For some reason if the redirect is a 301, it just forwards the POST request and payload. But I don't think I know enough about the difference between 301 and 307 to say why... :thinking:

[mstenta]

In HTTP 1.1, there actually is a status code (307) which indicates that the request should be repeated using the same method and post data.

https://softwareengineering.stackexchange.com/questions/99894/why-doesnt-http-have-post-redirect

[jgaehring]

Haha, yea, I think we're circling around the same conclusion, and I think it has a lot to do with that 307.

[mstenta]

Another thing worth noting: the app is currently making its first request over http - not https. This means that the credentials are being sent in plaintext. And then it's redirecting into https, but anyone in between the client and server would see the credentials.

[jgaehring]

In HTTP 1.1, there actually is a status code (307) which indicates that the request should be repeated using the same method and post data.

Interesting, so why is it changing the method? Maybe something to do with the fetch API?

[jgaehring]

Another thing worth noting: the app is currently making its first request over http - not https.

Oh also interesting. Hadn't thought of that. I need to figure out how to reproduce this error in my development environment so I can test these ideas....

[mstenta]

This means that the credentials are being sent in plaintext.

Actually, technically speaking, the username/password are not sent to /log - but the cookie and restws token are. But if we are authenticating /user/login over http, then the username+password is being sent plaintext.

[mstenta]

I have a feeling this issue is related to http vs https... just a hunch.

Can we use https by default, and detect if that doesn't work, and revert to http if that's the case?

Generally speaking, a server will either be set up to accept https or it won't. If it is, it will just work. If it isn't set up, then you won't be able to connect to the server at all because it won't be accepting traffic on port 443.

[jgaehring]

I know we discussed forcing https in the past, perhaps we should do that? Out of laziness, when I found that http requests to https servers were just redirected to https, but https requests to http servers failed, I just defaulted it to http. But we could just require all users of the app have an https server.

[jgaehring]

Ah, yea, we're on the same page. Do you think it's a good idea to allow http at all? It would not only be a heck of a lot safer, but also a lot simpler to just reject it, and let users know their server has to have SSL.

[mstenta]

I know we discussed forcing https in the past, perhaps we should do that? ... But we could just require all users of the app have an https server.

I don't think we need to require it - but we should try to use it on the first request. Because:

1. We default to sending encrypted credentials.
2. If it doesn't work, the entire request will fail - it won't be a weird redirect that we need to interpret (like it is when http is set up to auto-redirect to https). It just won't work. Which is easier to test for.... if the request doesn't work at all, try it on http instead.

A lot of the times, servers will be set up to auto-redirect from http to https, but there is rarely a reason to redirect in the other direction. So by using https as a default, we would generally be avoiding redirects too.

[mstenta]

I like the idea of encouraging HTTPS everywhere - but it would put another big burden on folks who want to set up farmOS themselves if we require it in the app. It would make local testing harder too, I imagine, since the Docker farmOS setup does not use HTTPS.

[mstenta]

In either case, it's worth testing to see if using https solves this issue first... Make sure we're on the right track.

[jgaehring]

Ok, here's my thoughts for how to proceed, to prevent going over time limits in dealing with this bug...

1. I implement the https-first/http-fallback procedure for all requests. This might take a little time, especially since I don't know if I can test this out in my dev env, which means compiling every time via PGB (such a pain). But, the trade-off is, even if this doesn't work for this bug, at least we've implemented a safer practice which we'd want anyways.
2. If that doesn't work, just go back to my original strategy of redirecting 404's back to the login page. It should be simple, fast, and we're pretty well guaranteed it should work since I've tested it already.

What's really weird, if you are right about this, is why this works right after a login attempt, but not after restart?

[mstenta]

Yea I think that makes sense.

What's really weird, if you are right about this, is why this works right after a login attempt, but not after restart?

Yea agreed - the inconsistency is strange. The request headers do appear to be different between the successful/unsuccessful first requests (which then result in different redirects). But why are they different is the question...

[mstenta]

Copied for easier comparison:

Successful Sync Attempt

First Request/Response

Request URL: http://test.farmos.net/log Request Method: POST Status Code: 307 Internal Redirect Referrer Policy: no-referrer-when-downgrade

Request Headers

Accept: json Content-Type: application/json Origin: file:// User-Agent: Mozilla/5.0 (Linux; Android 9; Pixel 3 Build/PQ1A.181205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/71.0.3578.99 Mobile Safari/537.36 X-CSRF-Token: ejY3koqA-pWzhd8hyl5qXoUvAOM66rrjzynspE8X9EM

Response Headers

HTTP/1.1 307 Internal Redirect Location: https://test.farmos.net/log Non-Authoritative-Reason: HSTS Access-Control-Allow-Origin: file:// Access-Control-Allow-Credentials: true

vs

Unsuccessful Sync Attempt

First Request/Response

Request URL: http://test.farmos.net/log Request Method: POST Status Code: 301 Moved Permanently Remote Address: 34.195.85.140:80 Referrer Policy: no-referrer-when-downgrade

Request Headers

POST /log HTTP/1.1 Host: test.farmos.net Connection: keep-alive Content-Length: 172 Accept: json Origin: file:// X-CSRF-Token: ejY3koqA-pWzhd8hyl5qXoUvAOM66rrjzynspE8X9EM User-Agent: Mozilla/5.0 (Linux; Android 9; Pixel 3 Build/PQ1A.181205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/71.0.3578.99 Mobile Safari/537.36 Content-Type: application/json Accept-Encoding: gzip, deflate Accept-Language: en-US Cookie: SESS9646fa17283c8d6f6c92f39f1c0e12b4=h6KEB8pWj1DgjUxsfcnHGKFOy34OVpJHdcQqPoIKkVk X-Requested-With: org.farmos.app

Response Headers

HTTP/1.1 301 Moved Permanently Server: nginx/1.11.10 Date: Wed, 26 Dec 2018 15:29:54 GMT Content-Type: text/html Content-Length: 186 Connection: keep-alive Location: https://test.farmos.net/log

[jgaehring]

The request headers do appear to be different between the successful/unsuccessful first requests (which then result in different redirects). But why are they different is the question...

Yea, I'll have to take a closer look at the fetch calls that are sending those POST requests, and also the fetch documentation, to see if there's something responsible for that difference.

[jgaehring]

One possible reason for a difference (although it opens new questions of its own), is that the headers shown with the successful attempt have the warning, "Provisional headers are shown":

Some details here: https://stackoverflow.com/questions/21177387/caution-provisional-headers-are-shown-in-chrome-debugger

[mstenta]

I was seeing that in my Chrome too, back when I was testing CORS stuff using farmOS on Docker localhost. I did some research into it, but forget where I landed. Notably, there was a difference between Chrome and Firefox in my CORS tests - where Firefox worked while Chrome did not (correlated to the "Provisional headers are shown" message, IIRC).

[jgaehring]

Well, it's ugly as hell with all the branching, but it seems to be working for both http and https servers now.

@mstenta , perhaps you could do some testing of the APK tonight or tmw before I close this out, run the iOS build and push it up to the Apple Store.

https://build.phonegap.com/apps/3295280/builds

:crossed_fingers:

[mstenta]

@jgaehring It seems to be working now. Sort of a strange flow, though...

After closing the app and reopening it, I created a new log, and when I clicked "Sync all to farmOS" it showed the login screen again, but with all the fields pre-populated. So I clicked "Submit credentials", which sent me back to the observations list page. Then I clicked "Sync all to farmOS" again and it worked.

[jgaehring]

After closing the app and reopening it, I created a new log, and when I clicked "Sync all to farmOS" it showed the login screen again, but with all the fields pre-populated.

Huh, that sounds like your token expired and you got a 403. Unrelated to this bug I'm guessing? Does that happen every time you close, reopen and sync?

[mstenta]

Oh huh... I tried again and it didn't happen the second time. So yea, maybe unrelated like you said.

[jgaehring]

Cool. Yea that process for the token expiration could be smoother, but I was leaving that for when we migrate to OAuth.