Unable to push forms to an aggregate server

[DavisRayM]

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

[ggalmazor]

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]

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]

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

[ggalmazor]

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]

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]

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]

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]

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]

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

[DavisRayM]

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]

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]

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]

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]

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]

Awesome, thanks! I'll check it now

[ggalmazor]

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

[ggalmazor]

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-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]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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

[DavisRayM]

@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]

Here's the debug log:

briefcase.log

[ggalmazor]

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]

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

[DavisRayM]

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

[ggalmazor]

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