Unable to push forms to an aggregate server #852

DavisRayM · 2020-01-23T14:06:49Z

Software versions

Briefcase v1.17.2, MacOS Mojave, onadata v2.1.2

Problem description

Pushing a form to onadata freezes on Sending Form.

Steps to reproduce the problem

Push a form(that doesn't exist in your account) to ona.io using v1.17.2

Expected behavior

The form should be pushed or an error should be raised on failure.

Other information

Briefcase log: briefcase(2).log
Related issue: #801

The text was updated successfully, but these errors were encountered:

ggalmazor · 2020-03-02T17:37:58Z

Hi, @DavisRayM!

Before starting to comment on my findings, I have a question about the correct URL one should use. Should I use https://ona.io or https://ona.io/ggalmazor?

On to the issue now:

Let's establish first that Briefcase doesn't follow 302s. This is important because Ona will redirect /formUpload to /formUpload/.

If I use https://ona.io/ggalmazor as the server's URL, then this is the sequence of request that I can see:

Seq.	Request	Response
1	GET /ggalmazor/formList (no auth info)	401
2	GET /ggalmazor/formList (digest challenge)	200 + Cookies (`AWSALB`, `AWSALBCORS`)
3	POST /ggalmazor/formUpload (cookies)	401 *

Briefcase reports an error in the logs because Ona's response declares a content length of 114, but the response payload is actually empty. Not important, though.

So, taking a look at this exchange, I'm not sure what would we have to change... An Aggregate server would set and reuse session cookies to continue an authenticated exchange after the second request. What would Ona require in this instance? I'm also curious about previous versions of Briefcase. Perhaps we broke something related to auth in recent releases?

Please advise.

DavisRayM · 2020-03-03T06:29:04Z

Hi, @DavisRayM!

Before starting to comment on my findings, I have a question about the correct URL one should use. Should I use https://ona.io or https://ona.io/ggalmazor?

On to the issue now:

Let's establish first that Briefcase doesn't follow 302s. This is important because Ona will redirect /formUpload to /formUpload/.

If I use https://ona.io/ggalmazor as the server's URL, then this is the sequence of request that I can see:
Seq. Request Response
1 GET /ggalmazor/formList (no auth info) 401
2 GET /ggalmazor/formList (digest challenge) 200 + Cookies (AWSALB, AWSALBCORS)
3 POST /ggalmazor/formUpload (cookies) 401 *
* Briefcase reports an error in the logs because Ona's response declares a content length of 114, but the response payload is actually empty. Not important, though.
So, taking a look at this exchange, I'm not sure what would we have to change... An Aggregate server would set and reuse session cookies to continue an authenticated exchange after the second request. What would Ona require in this instance? I'm also curious about previous versions of Briefcase. Perhaps we broke something related to auth in recent releases?

Please advise.

Hi @ggalmazor,

Thank you for investigating this. The correct / advised endpoint to use on ona is http://api.ona.io/ggalmzor.

In regards to the sequence of requests expected by Ona: Currently onadata expects all requests to be authenticated via digest auth. We don't utilize session cookies on our ODK endpoints afaik (This seems like something we should do... I'll bring this up on the onadata side).

Ideal Sequence of requests

Seq	Request	Response
1	GET /draymond/formList(no auth info)	401
2	GET /draymond/formList(digest challenge response)	200
3	POST /draymond/formUpload (digest challenge response)	201

Sequence of request Briefcase v1.15.0 (and previous)

Seq	Request	Response
1	GET /draymond/formList(no auth info)	401
2	GET /draymond/formList(digest challenge response)	200
3	POST /draymond/formUpload (no auth info, possibly cookies? not sure)	401
4	POST /draymond/formUpload (digest challenge response)	201

DavisRayM · 2020-03-04T06:31:08Z

@ggalmazor I'm curious is this change on our end required for other ODK tools(Collect) ?

ggalmazor · 2020-03-04T10:44:11Z

Hi, @DavisRayM!

After discussing this with @lognaturel, we agreed on trying to bring back the retries from v1.15 and previous versions, since the OpenRosa standard doesn't tell anything about cookies.

@ggalmazor I'm curious is this change on our end required for other ODK tools(Collect) ?

I'm not sure. In any case, let's wait to see how difficult is going to be to have those retries back in Briefcase.

DavisRayM · 2020-03-04T10:53:32Z

That would be awesome. I'd like to help where I can, I'm not really used to Java but would like to learn it.... A few pointers on what the change may entail and I can possibly work on it, if that's fine ?

Hi, @DavisRayM!

After discussing this with @lognaturel, we agreed on trying to bring back the retries from v1.15 and previous versions, since the OpenRosa standard doesn't tell anything about cookies.

@ggalmazor I'm curious is this change on our end required for other ODK tools(Collect) ?

I'm not sure. In any case, let's wait to see how difficult is going to be to have those retries back in Briefcase.

ggalmazor · 2020-03-09T11:23:26Z

I'd like to help where I can, I'm not really used to Java but would like to learn it.... A few pointers on what the change may entail and I can possibly work on it, if that's fine ?

That'd be great, although I'm still exploring this issue... I think for now the most useful thing would be to confirm whether Ona is setting the correct value in the Content-Length header to the 401 responses. I'm getting a length of 114 bytes but the payload comes empty and Briefcase crashes when trying to consume it. This is the response I'm getting right now to the POST /ggalmazor/formUpload request:

HTTP/1.1 401 Unauthorized
Date: Mon, 09 Mar 2020 11:10:37 GMT
Content-Type: text/xml; charset=utf-8
Content-Length: 114
Connection: keep-alive
Set-Cookie: AWSALB=yqsbZOWEE6zkxS/xaU9aSwIQoTP4/038DmzmqVvRLOL9yqa4fw16r1Qx6i7nDIggvHUYLdIJO0rDZv+jD8PkfH6qALxZIGZDLXxav4i+oB2W4EGrN1HMBzcVI0Ue; Expires=Mon, 16 Mar 2020 11:10:37 GMT; Path=/
Set-Cookie: AWSALBCORS=yqsbZOWEE6zkxS/xaU9aSwIQoTP4/038DmzmqVvRLOL9yqa4fw16r1Qx6i7nDIggvHUYLdIJO0rDZv+jD8PkfH6qALxZIGZDLXxav4i+oB2W4EGrN1HMBzcVI0Ue; Expires=Mon, 16 Mar 2020 11:10:37 GMT; Path=/; SameSite=None; Secure
Server: nginx
WWW-Authenticate: Digest realm="DJANGO", qop="auth", nonce="1583752237.5864062:C594:40ca891aaaab360419098d72d3d8bce8", opaque="A81D19359CF688CD5E3A704BE4DD6602", algorithm="MD5", stale="false"
Vary: Accept, Origin, Accept-Language, Cookie
Allow: POST, HEAD, OPTIONS
X-Frame-Options: DENY
Content-Language: en
Set-Cookie: multidb_pin_writes=y; expires=Mon, 09 Mar 2020 11:10:47 GMT; Max-Age=10; Path=/

end of stream

OTOH, this is the 401 response to a GET /ggalmazor/formList that we do before the above POST:

HTTP/1.1 401 Unauthorized
Date: Mon, 09 Mar 2020 11:38:38 GMT
Content-Type: text/xml; charset=utf-8
Content-Length: 164
Connection: keep-alive
Set-Cookie: AWSALB=hzE9itUhdMKWZGHZXR36Quhz6cFxNQwS/g2FvZa7tS5n+imJ8Suh6CtEcsB7khv8dF6QcbtCKFeNe77h8jw1ODLmZso164hIIk4vGQnuqMZHkjJyw8o842p10vwy; Expires=Mon, 16 Mar 2020 11:38:38 GMT; Path=/
Set-Cookie: AWSALBCORS=hzE9itUhdMKWZGHZXR36Quhz6cFxNQwS/g2FvZa7tS5n+imJ8Suh6CtEcsB7khv8dF6QcbtCKFeNe77h8jw1ODLmZso164hIIk4vGQnuqMZHkjJyw8o842p10vwy; Expires=Mon, 16 Mar 2020 11:38:38 GMT; Path=/; SameSite=None; Secure
Server: nginx
WWW-Authenticate: Digest realm="DJANGO", qop="auth", nonce="1583753918.141645:CFAA:6dc1bf69bfc63d2f350190a88de30abb", opaque="3D75C3DF017D4D3AA98617827684E9ED", algorithm="MD5", stale="false"
Allow: GET, HEAD, OPTIONS
X-Frame-Options: DENY
Vary: Origin, Accept-Language, Cookie
Content-Language: en
ETag: "961b08f8461b77aa29ca411d09699ca8"

<?xml version="1.0" encoding="utf-8"?>
<xforms xmlns="http://openrosa.org/xforms/xformsList"><detail>Authentication credentials were not provided.</detail></xforms>

The payload from this one matches the Content-Length of 164 bytes. When Briefcase gets this 401, it retries the request with the auth header.

At this moment, I'm suspecting that the crash from trying to read the POST response's payload is preventing Briefcase from sending the authenticated POST after the 401.

DavisRayM · 2020-03-09T12:29:16Z

Mhh that's weird, the response with content-length 114 should have the following content on both endpoints:

Let me investigate this for a bit in onadata. Will comment once I found out why this is happening.

ggalmazor · 2020-03-09T12:30:40Z

Thanks! Also, note that that response is more than 114 bytes long!

https://mothereff.in/byte-counter has proven to be useful lately :D

ggalmazor · 2020-03-09T12:31:24Z

In the meantime, I'm exploring alternative ways to make the request so that we don't crash for that reason.

DavisRayM · 2020-03-09T12:45:47Z

Thanks! Also, note that that response is more than 114 bytes long!

https://mothereff.in/byte-counter has proven to be useful lately :D

Might have something to do with the \n usually escaped into a new line ~~'Enter' I can't seem to find the word here for some reason 😓 (see below for what the actual content looks like)~~. The content_length in Django (We usually use the common middleware from django to automatically set the content-length) is usually gotten from the length of the content in this case len(string) would be 114 but if I were to use a length counter online or something of the sort it would be 115.

<?xml version="1.0" encoding="utf-8"?>
<root><detail>Authentication credentials were not provided.</detail></root>

Keeping the above in https://mothereff.in/byte-counter will calculate the right content-length

ggalmazor · 2020-03-09T12:47:10Z

OK, I see.

If you can confirm that Ona actually responds that content, then Briefcase might be closing the connection too early, which would explain why it's failing to read the payload.

ggalmazor · 2020-03-09T14:16:32Z

OK, @DavisRayM!

I've confirmed that I get truncated 401 responses from Ona using curl:

guillermo@gigidesktop:/tmp/ona$ curl -v -X POST -d @./payload.txt -H "Content-Type: multipart/form-data; boundary=HtwYIoDpHGlSKirfXvazQUsnGlCELEHxNTo_" -H "X-OpenRosa-Version: 1.0" https://ona.io/ggalmazor/formUpload
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 52.28.25.102...
* TCP_NODELAY set
* Connected to ona.io (52.28.25.102) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: OU=Domain Control Validated; OU=Gandi Standard Wildcard SSL; CN=*.ona.io
*  start date: Dec  1 00:00:00 2019 GMT
*  expire date: Dec  9 23:59:59 2021 GMT
*  subjectAltName: host "ona.io" matched cert's "ona.io"
*  issuer: C=FR; ST=Paris; L=Paris; O=Gandi; CN=Gandi Standard SSL CA 2
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x55bd103af580)
> POST /ggalmazor/formUpload HTTP/2
> Host: ona.io
> User-Agent: curl/7.58.0
> Accept: */*
> Content-Type: multipart/form-data; boundary=HtwYIoDpHGlSKirfXvazQUsnGlCELEHxNTo_
> X-OpenRosa-Version: 1.0
> Content-Length: 9180
> 
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* We are completely uploaded and fine
< HTTP/2 401 
< date: Mon, 09 Mar 2020 14:15:30 GMT
< content-type: text/xml; charset=utf-8
< content-length: 114
< set-cookie: AWSALB=76H7Wx81AAz2oaZ7GWKyj3l+jXgY7j612dJTL1dVU6ylfz/6909CR6WiAsBu2N6BfVorVwczOVnC2VewaIRbSmbCp/tuib4dXCgnSYztDORU+mB357ixL7nYf6pt; Expires=Mon, 16 Mar 2020 14:15:30 GMT; Path=/
< set-cookie: AWSALBCORS=76H7Wx81AAz2oaZ7GWKyj3l+jXgY7j612dJTL1dVU6ylfz/6909CR6WiAsBu2N6BfVorVwczOVnC2VewaIRbSmbCp/tuib4dXCgnSYztDORU+mB357ixL7nYf6pt; Expires=Mon, 16 Mar 2020 14:15:30 GMT; Path=/; SameSite=None; Secure
< server: nginx
< www-authenticate: Digest realm="DJANGO", qop="auth", nonce="1583763330.0836592:6B31:c4bd17b2863d4f3ab3e17bb19a75d7c2", opaque="C67F326C0BDA3F80DE86A572E401BAC7", algorithm="MD5", stale="false"
< vary: Accept, Origin, Accept-Language, Cookie
< allow: POST, HEAD, OPTIONS
< x-frame-options: DENY
< content-language: en
< set-cookie: multidb_pin_writes=y; expires=Mon, 09 Mar 2020 14:15:40 GMT; Max-Age=10; Path=/
< 
* HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)
* Connection #0 to host ona.io left intact
curl: (92) HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)

(not really important, but here's the payload file: payload.txt)

From my end, it looks like Ona is closing the connection after writing the headers.

DavisRayM · 2020-03-10T06:10:34Z

Hey @ggalmazor, sorry for the late response. We don't seem to be doing anything different on the /formList vs /formUpload endpoints.

OK, I see.

If you can confirm that Ona actually responds that content, then Briefcase might be closing the connection too early, which would explain why it's failing to read the payload.

Mhh let me look into this.... I'm not sure why the connections are being closed.

OK, @DavisRayM!

I've confirmed that I get truncated 401 responses from Ona using curl:

guillermo@gigidesktop:/tmp/ona$ curl -v -X POST -d @./payload.txt -H "Content-Type: multipart/form-data; boundary=HtwYIoDpHGlSKirfXvazQUsnGlCELEHxNTo_" -H "X-OpenRosa-Version: 1.0" https://ona.io/ggalmazor/formUpload
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 52.28.25.102...
* TCP_NODELAY set
* Connected to ona.io (52.28.25.102) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: OU=Domain Control Validated; OU=Gandi Standard Wildcard SSL; CN=*.ona.io
*  start date: Dec  1 00:00:00 2019 GMT
*  expire date: Dec  9 23:59:59 2021 GMT
*  subjectAltName: host "ona.io" matched cert's "ona.io"
*  issuer: C=FR; ST=Paris; L=Paris; O=Gandi; CN=Gandi Standard SSL CA 2
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x55bd103af580)
> POST /ggalmazor/formUpload HTTP/2
> Host: ona.io
> User-Agent: curl/7.58.0
> Accept: */*
> Content-Type: multipart/form-data; boundary=HtwYIoDpHGlSKirfXvazQUsnGlCELEHxNTo_
> X-OpenRosa-Version: 1.0
> Content-Length: 9180
> 
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* We are completely uploaded and fine
< HTTP/2 401 
< date: Mon, 09 Mar 2020 14:15:30 GMT
< content-type: text/xml; charset=utf-8
< content-length: 114
< set-cookie: AWSALB=76H7Wx81AAz2oaZ7GWKyj3l+jXgY7j612dJTL1dVU6ylfz/6909CR6WiAsBu2N6BfVorVwczOVnC2VewaIRbSmbCp/tuib4dXCgnSYztDORU+mB357ixL7nYf6pt; Expires=Mon, 16 Mar 2020 14:15:30 GMT; Path=/
< set-cookie: AWSALBCORS=76H7Wx81AAz2oaZ7GWKyj3l+jXgY7j612dJTL1dVU6ylfz/6909CR6WiAsBu2N6BfVorVwczOVnC2VewaIRbSmbCp/tuib4dXCgnSYztDORU+mB357ixL7nYf6pt; Expires=Mon, 16 Mar 2020 14:15:30 GMT; Path=/; SameSite=None; Secure
< server: nginx
< www-authenticate: Digest realm="DJANGO", qop="auth", nonce="1583763330.0836592:6B31:c4bd17b2863d4f3ab3e17bb19a75d7c2", opaque="C67F326C0BDA3F80DE86A572E401BAC7", algorithm="MD5", stale="false"
< vary: Accept, Origin, Accept-Language, Cookie
< allow: POST, HEAD, OPTIONS
< x-frame-options: DENY
< content-language: en
< set-cookie: multidb_pin_writes=y; expires=Mon, 09 Mar 2020 14:15:40 GMT; Max-Age=10; Path=/
< 
* HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)
* Connection #0 to host ona.io left intact
curl: (92) HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)

(not really important, but here's the payload file: payload.txt)

From my end, it looks like Ona is closing the connection after writing the headers.

DavisRayM · 2020-03-10T09:55:36Z

We've been able to replicate and kind of fix the connection close issue (still happens intermittently looking towards fixing that completely). Encountered the following error on Briefcase though.

Please use stage-odk.ona.io, for testing (Hopefully will get the connection close issues resolved in a bit)

ggalmazor · 2020-03-10T09:59:40Z

Awesome, thanks! I'll check it now

ggalmazor · 2020-03-10T10:11:26Z

Huh... I'm getting non-empty responses with my curl command, but Briefcase keeps getting them empty... Any ideas?

ggalmazor · 2020-03-10T10:12:14Z

Encountered the following error on Briefcase though.

Could you copy the text from that error stacktrace here so that I can debug it?

DavisRayM · 2020-03-10T10:15:54Z

2020-03-10 12:48:12,492 [ForkJoinPool-17-worker-3] ERROR o.o.briefcase.reused.job.JobsRunner - Error running Job
java.io.UncheckedIOException: org.apache.http.client.ClientProtocolException
	at org.opendatakit.briefcase.reused.http.CommonsHttp.uncheckedExecute(CommonsHttp.java:146)
	at org.opendatakit.briefcase.reused.http.CommonsHttp.execute(CommonsHttp.java:94)
	at org.opendatakit.briefcase.push.aggregate.PushToAggregate.pushSubmissionAndAttachments(PushToAggregate.java:185)
	at org.opendatakit.briefcase.push.aggregate.PushToAggregate.lambda$push$5(PushToAggregate.java:103)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1507)
	at org.opendatakit.briefcase.push.aggregate.PushToAggregate.lambda$push$6(PushToAggregate.java:102)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1621)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.ForEachOps$ForEachTask.compute(ForEachOps.java:290)
	at java.base/java.util.concurrent.CountedCompleter.exec(CountedCompleter.java:746)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1016)
	at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1665)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1598)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
Caused by: org.apache.http.client.ClientProtocolException: null
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:187)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
	at org.apache.http.client.fluent.Request.internalExecute(Request.java:173)
	at org.apache.http.client.fluent.Executor.execute(Executor.java:262)
	at org.opendatakit.briefcase.reused.http.CommonsHttp.uncheckedExecute(CommonsHttp.java:139)
	... 15 common frames omitted
Caused by: org.apache.http.client.NonRepeatableRequestException: Cannot retry request with a non-repeatable request entity.
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:226)
	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
	... 20 common frames omitted

ggalmazor · 2020-03-10T10:16:51Z

Thanks! I think I have a working solution for the non-repeatable request error in that stacktrace. Let's see if I can sort out the empty response issue now...

DavisRayM · 2020-03-10T10:16:56Z

Still looking into this but the only way to kind of bypass this, is to retry 😅 .

Huh... I'm getting non-empty responses with my curl command, but Briefcase keeps getting them empty... Any ideas?

DavisRayM · 2020-03-10T10:18:14Z

If you have a branch with the suspected fix, I could try it out on my side. The retrying bit can get a bit annoying

ggalmazor · 2020-03-10T10:19:22Z

The weird thing is that I'm launching both things (curl and Briefcase push) almost at the same time and I'm consistently getting non-empty responses with curl, and empty ones with Briefcase :/

DavisRayM · 2020-03-10T10:23:33Z

Yea, I had the same issue a while back.... We have buffering enabled on post requests(the weird connection close happens if it isn't) but for some reason it just fails sometimes.

ggalmazor · 2020-03-10T10:24:08Z

I just got one through! :) Yay!

Well, I got a 404 error while sending a submission now. Here's the HTTP exchange log:

POST /ggalmazor/submission HTTP/1.1
X-OpenRosa-Version: 1.0
X-OpenRosa-Version: 1.0
Date: Tue, 10 Mar 2020 11:19:41 +0100
Content-Length: 692
Content-Type: multipart/form-data; boundary=9D0Uiue-qnf5ccvX7Oz2F1L_lEfsp_zBlDhI4
Host: stage-odk.ona.io
Connection: Keep-Alive
User-Agent: Apache-HttpClient/4.5.5 (Java/11.0.5)
Cookie: multidb_pin_writes=y
Accept-Encoding: gzip,deflate

--9D0Uiue-qnf5ccvX7Oz2F1L_lEfsp_zBlDhI4
Content-Disposition: form-data; name="xml_submission_file"; filename="submission.xml"
Content-Type: application/xml
Content-Transfer-Encoding: binary

<data id="build_Data-Responden_1583135226" instanceID="uuid:47bcf3e3-9ef4-4201-aedb-ad690d6dcffb" submissionDate="2020-03-02T07:49:32.379Z" isComplete="true" markedAsCompleteDate="2020-03-02T07:49:32.379Z" xmlns="http://opendatakit.org/submissions"><n0:meta xmlns:n0="http://openrosa.org/xforms"><n0:instanceID>uuid:47bcf3e3-9ef4-4201-aedb-ad690d6dcffb</n0:instanceID></n0:meta><NamaResponden>Lina amalia</NamaResponden><JK>2</JK><Usia>2</Usia></data>
--9D0Uiue-qnf5ccvX7Oz2F1L_lEfsp_zBlDhI4--

HTTP/1.1 401 Unauthorized
Date: Tue, 10 Mar 2020 10:19:41 GMT
Content-Type: text/xml; charset=utf-8
Content-Length: 114
Connection: keep-alive
Server: nginx/1.16.1
WWW-Authenticate: Digest realm="DJANGO", qop="auth", nonce="1583835581.4218807:ACE2:12fda06e741bd865dee675012d375ddd", opaque="CA025A04325EDE362436E48291EFA11B", algorithm="MD5", stale="false"
Vary: Accept, Origin, Accept-Language, Cookie
Allow: POST, HEAD, OPTIONS
X-OpenRosa-Version: 1.0
X-OpenRosa-Accept-Content-Length: 100000000
Location: https://stage-odk.ona.io/ggalmazor/submission
X-Frame-Options: DENY
Content-Language: en
Set-Cookie: multidb_pin_writes=y; expires=Tue, 10 Mar 2020 10:19:51 GMT; Max-Age=10; Path=/

<?xml version="1.0" encoding="utf-8"?>
<root><detail>Authentication credentials were not provided.</detail></root>

POST /ggalmazor/submission HTTP/1.1
X-OpenRosa-Version: 1.0
X-OpenRosa-Version: 1.0
Date: Tue, 10 Mar 2020 11:19:41 +0100
Content-Length: 692
Content-Type: multipart/form-data; boundary=9D0Uiue-qnf5ccvX7Oz2F1L_lEfsp_zBlDhI4
Host: stage-odk.ona.io
Connection: Keep-Alive
User-Agent: Apache-HttpClient/4.5.5 (Java/11.0.5)
Cookie: multidb_pin_writes=y
Accept-Encoding: gzip,deflate
Authorization: Digest username="ggalmazor", realm="DJANGO", nonce="1583835581.4218807:ACE2:12fda06e741bd865dee675012d375ddd", uri="/ggalmazor/submission", response="46af785a8ba371a2c74a9f6a7f167272", qop=auth, nc=00000001, cnonce="94e068c0143f240b", algorithm=MD5, opaque="CA025A04325EDE362436E48291EFA11B"

--9D0Uiue-qnf5ccvX7Oz2F1L_lEfsp_zBlDhI4
Content-Disposition: form-data; name="xml_submission_file"; filename="submission.xml"
Content-Type: application/xml
Content-Transfer-Encoding: binary

<data id="build_Data-Responden_1583135226" instanceID="uuid:47bcf3e3-9ef4-4201-aedb-ad690d6dcffb" submissionDate="2020-03-02T07:49:32.379Z" isComplete="true" markedAsCompleteDate="2020-03-02T07:49:32.379Z" xmlns="http://opendatakit.org/submissions"><n0:meta xmlns:n0="http://openrosa.org/xforms"><n0:instanceID>uuid:47bcf3e3-9ef4-4201-aedb-ad690d6dcffb</n0:instanceID></n0:meta><NamaResponden>Lina amalia</NamaResponden><JK>2</JK><Usia>2</Usia></data>
--9D0Uiue-qnf5ccvX7Oz2F1L_lEfsp_zBlDhI4--

HTTP/1.1 404 Not Found
Date: Tue, 10 Mar 2020 10:19:41 GMT
Content-Type: text/xml; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Server: nginx/1.16.1
Vary: Accept-Encoding
Vary: Accept, Origin, Accept-Language, Cookie
Allow: POST, HEAD, OPTIONS
X-OpenRosa-Version: 1.0
X-OpenRosa-Accept-Content-Length: 100000000
Location: https://stage-odk.ona.io/ggalmazor/submission
X-Frame-Options: DENY
Content-Language: en
Set-Cookie: multidb_pin_writes=y; expires=Tue, 10 Mar 2020 10:19:51 GMT; Max-Age=10; Path=/
Content-Encoding: gzip

5b
[0x1f][0x8b][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x3][0xb3][0xb1][0xaf][0xc8][0xcd]Q(K-*[0xce][0xcc][0xcf][0xb3]U2[0xd4]3PRH[0xcd]K[0xce]O[0xc9][0xcc]K[0xb7]U*-I[0xd3][0xb5]P[0xb2][0xb7][0xe3][0xb2])[0xca][0xcf]/[0xb1][0xb3]II-I[0xcc][0xcc][0xb1][0xf3][0xcb]/QH[0xcb]/[0xcd]K[0xd1][0xb3][0xd1][0x87]
[0xd9][0xe8][0x83]U[0x0][0x0][0xa7][0xf5][0x1c][0x8a]O[0x0][0x0][0x0]
0

It works as expected:

First, it tries to send the submission without an auth header. It gets a 401 with an auth challenge
Then it retries the request with an auth header.

Not sure why I'm getting a 404, though.

DavisRayM · 2020-03-10T10:27:06Z

Awesome! I'm not quite sure exactly why you got a 404 but one reason would be that the XForm version specified in the submission xml is not the same as the one onadata has.

I'll look into solving the connection issue.

ggalmazor · 2020-03-10T10:57:20Z

OK, let's recap then:

It looks like Briefcase retries requests after 401s answering auth challenges by the server, as expected.
It looks like Briefcase can't resend some requests

I'm currently investigating this and I think I've found a way to improve it. Since it looks like you can reproduce this error in your environment, I'll push a branch with the changes so that you can verify whether it helps with the issue or not.

DavisRayM · 2020-03-10T12:07:20Z

Sounds about right.

OK, let's recap then:

* It looks like Briefcase retries requests after 401s answering auth challenges by the server, as expected.

* It looks like Briefcase can't resend some requests
  I'm currently investigating this and I think I've found a way to improve it. Since it looks like you can reproduce this error in your environment, I'll push a branch with the changes so that you can verify whether it helps with the issue or not.

ggalmazor · 2020-03-10T12:11:12Z

OK, I've pushed the change to make repeatable requests here: https://github.com/ggalmazor/briefcase/tree/repeatable_http_requests

Let me know if that solves the issue you're seeing. I've tried to reproduce it in my computer without success so far.

DavisRayM · 2020-03-10T12:19:01Z

Nice, let me test it out. I hope the connection issue is solved on your side when using stage-odk.ona.io ?

DavisRayM · 2020-03-10T13:11:25Z

@ggalmazor Able to replicate the issue by trying to push a form that doesn't exist on ona(no submission data).

2020-03-10 16:10:00,086 [ForkJoinPool-3-worker-1] INFO  o.o.b.p.a.PushToAggregateTracker - Push require - Start pushing form and submissions
2020-03-10 16:10:00,829 [ForkJoinPool-3-worker-1] INFO  o.o.b.p.a.PushToAggregateTracker - Push require - Form doesn't exist in Aggregate
2020-03-10 16:10:00,833 [ForkJoinPool-3-worker-1] INFO  o.o.b.p.a.PushToAggregateTracker - Push require - Sending form
2020-03-10 16:10:01,033 [ForkJoinPool-3-worker-1] ERROR o.o.briefcase.reused.job.JobsRunner - Error running Job
java.io.UncheckedIOException: org.apache.http.client.ClientProtocolException
	at org.opendatakit.briefcase.reused.http.CommonsHttp.uncheckedExecute(CommonsHttp.java:146)
	at org.opendatakit.briefcase.reused.http.CommonsHttp.execute(CommonsHttp.java:94)
	at org.opendatakit.briefcase.push.aggregate.PushToAggregate.pushFormAndAttachments(PushToAggregate.java:167)
	at org.opendatakit.briefcase.push.aggregate.PushToAggregate.pushFormAndAttachments(PushToAggregate.java:157)
	at org.opendatakit.briefcase.push.aggregate.PushToAggregate.lambda$push$3(PushToAggregate.java:79)
	at org.opendatakit.briefcase.reused.job.Job.lambda$thenAccept$8(Job.java:134)
	at org.opendatakit.briefcase.reused.job.Job.lambda$thenSupply$9(Job.java:145)
	at org.opendatakit.briefcase.reused.job.Job.lambda$thenAccept$8(Job.java:133)
	at org.opendatakit.briefcase.reused.job.Job.lambda$thenRun$6(Job.java:109)
	at org.opendatakit.briefcase.reused.job.JobsRunner.lambda$null$1(JobsRunner.java:65)
	at java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1386)
	at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
	at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
Caused by: org.apache.http.client.ClientProtocolException: null
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:187)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
	at org.apache.http.client.fluent.Request.internalExecute(Request.java:173)
	at org.apache.http.client.fluent.Executor.execute(Executor.java:262)
	at org.opendatakit.briefcase.reused.http.CommonsHttp.uncheckedExecute(CommonsHttp.java:139)
	... 14 common frames omitted
Caused by: org.apache.http.client.NonRepeatableRequestException: Cannot retry request with a non-repeatable request entity.
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:226)
	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
	... 19 common frames omitted

DavisRayM · 2020-03-10T13:16:40Z

Here's the debug log:

briefcase.log

ggalmazor · 2020-03-11T11:22:49Z

Hi, @DavisRayM! It looks like I messed up the branch I linked yesterday and it didn't have the fix. I'm sorry for making you lose time on this.

I've created a PR with the fix at #856. Could you try again with the code from that PR, please?

DavisRayM · 2020-03-11T11:24:17Z

Hey, no worries at all. Let me try it out.

DavisRayM · 2020-03-11T11:34:34Z

@ggalmazor The fix seems to work fine on my side. Able to push forms and submissions now 🎉

ggalmazor · 2020-03-11T15:23:29Z

Awesome! I'll fix this for review and QA then. Let's see if we can get this shipped by Friday tops

DavisRayM changed the title ~~Unable to push form to an Aggregate server~~ Unable to push forms to an aggregate server Jan 23, 2020

DavisRayM mentioned this issue Jan 27, 2020

ODK Briefcase v1.17+ Support onaio/onadata#1763

Closed

ggalmazor mentioned this issue Mar 11, 2020

Make HTTP POST requests repeatable #856

Merged

ggalmazor closed this as completed in #856 Mar 13, 2020

Unable to push forms to an aggregate server #852

Unable to push forms to an aggregate server #852

Comments

DavisRayM commented Jan 23, 2020 • edited Loading

Software versions

Problem description

Steps to reproduce the problem

Expected behavior

Other information

ggalmazor commented Mar 2, 2020

DavisRayM commented Mar 3, 2020 • edited Loading

Ideal Sequence of requests

Sequence of request Briefcase v1.15.0 (and previous)

DavisRayM commented Mar 4, 2020

ggalmazor commented Mar 4, 2020

DavisRayM commented Mar 4, 2020 • edited Loading

ggalmazor commented Mar 9, 2020 • edited Loading

DavisRayM commented Mar 9, 2020 • edited Loading

ggalmazor commented Mar 9, 2020

ggalmazor commented Mar 9, 2020

DavisRayM commented Mar 9, 2020 • edited Loading

ggalmazor commented Mar 9, 2020

ggalmazor commented Mar 9, 2020 • edited Loading

DavisRayM commented Mar 10, 2020

DavisRayM commented Mar 10, 2020

ggalmazor commented Mar 10, 2020

ggalmazor commented Mar 10, 2020

ggalmazor commented Mar 10, 2020

DavisRayM commented Mar 10, 2020

ggalmazor commented Mar 10, 2020

DavisRayM commented Mar 10, 2020 • edited Loading

DavisRayM commented Mar 10, 2020

ggalmazor commented Mar 10, 2020

DavisRayM commented Mar 10, 2020

ggalmazor commented Mar 10, 2020

DavisRayM commented Mar 10, 2020 • edited Loading

ggalmazor commented Mar 10, 2020

DavisRayM commented Mar 10, 2020

ggalmazor commented Mar 10, 2020

DavisRayM commented Mar 10, 2020

DavisRayM commented Mar 10, 2020 • edited Loading

DavisRayM commented Mar 10, 2020 • edited Loading

ggalmazor commented Mar 11, 2020

DavisRayM commented Mar 11, 2020

DavisRayM commented Mar 11, 2020

ggalmazor commented Mar 11, 2020

DavisRayM commented Jan 23, 2020 •

edited

Loading

DavisRayM commented Mar 3, 2020 •

edited

Loading

DavisRayM commented Mar 4, 2020 •

edited

Loading

ggalmazor commented Mar 9, 2020 •

edited

Loading

DavisRayM commented Mar 9, 2020 •

edited

Loading

DavisRayM commented Mar 9, 2020 •

edited

Loading

ggalmazor commented Mar 9, 2020 •

edited

Loading

DavisRayM commented Mar 10, 2020 •

edited

Loading

DavisRayM commented Mar 10, 2020 •

edited

Loading

DavisRayM commented Mar 10, 2020 •

edited

Loading

DavisRayM commented Mar 10, 2020 •

edited

Loading