1.x: REST request not reaching the couchbase lite java listener.

[NitzDKoder]

Hi Folks,

1)App design similar to Couchbase-Lite-PhoneGap-Plugin
https://github.com/couchbaselabs/Couchbase-Lite-PhoneGap-Plugin

2. App HTML/JS code does REST using -->>> modules.js(https request formation and timeouts) ---> Android Webview --->> couchbase lite java listener

https://github.com/couchbaselabs/TodoLite-PhoneGap/blob/f1a810f9408a9807f3bf25ae69ba1d6a6aaee71c/js/modules.js

3)Heartbeat for DB changes(_changes) is 5 mins.

4. After idle the REST request from HTML/JS fails to get response from server.

Logs Analysis:

Success case:

App JS:

[08/28 17:40:08:006] [HTML5LOG] cblPtxInterface.syncManager()-> doCancelPost()-> Stop Sync = {"target":"ptxdata","source":{"url":"https://AAAAAAAAAAAA:XXXXXXXXXXXXXXXXX@mydomain/data"},"continuous":true,"filter":"sync_gateway/bychannel","query_params":{"channels":"PTX-919480109390-meta-CH,919480109390-CH"}}
[08/28 17:40:08:013] [HTML5LOG] ReSTCBL ::: Request started::{"id":"139: POST https://:@localdomain:14480/_replicate"}
[08/28 17:40:08:083] [HTML5LOG] ReSTCBL ::: Got response::{"id":"139: POST https://:@localdomain:14480/_replicate","status":200}

App Webview:

[08/28 17:40:08:019] WhitelistPlugin ---------- cblURL: https://:@localdomain:14480/
[08/28 17:40:08:020] WhitelistPlugin ---------- CBL URL allowed to Navigate -----

Couchbase Logs:

 [08/28 05:40:08.061] [4] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@2116a1d0) POST: https://localdomain:14480/_replicate
[08/28 05:40:08.061] [4] Listener: authHeader is null
[08/28 05:40:08.062] [4] Listener: Not enforcing basic auth -- allowedCredentials null or empty
[08/28 05:40:08.062] [4] Listener: remoteURL() addr=localdomain
[08/28 05:40:08.064] [4] Database: getDatabase() com.couchbase.lite.Manager@1da33ad9 com.couchbase.lite.Database@37445c9e[/data/data/com.xxx.app/files/data.cblite2]
[08/28 05:40:08.068] [4] Sync: PullerInternal{https://---:---@mydomain/data, pull, 1856e} [fireTrigger()] => STOP_GRACEFUL
[08/28 05:40:08.069] [4] Listener: RouterCallbackBlock.onResponseReady() START
[08/28 05:40:08.069] [16] Sync: firing trigger: STOP_GRACEFUL
[08/28 05:40:08.070] [4] Listener: RouterCallbackBlock.onResponseReady() END
[08/28 05:40:08.072] [4] Listener: CountDownLatch.await() START
[08/28 05:40:08.072] [4] Listener: CountDownLatch.await() END

Failure case:

App JS:

Line 2050: [08/28 17:54:22:685] [HTML5LOG] ReSTCBL ::: Request started::{"id":"142: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2052: [08/28 17:59:22:697] [HTML5LOG] ReSTCBL ::: Request started::{"id":"143: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2054: [08/28 18:04:22:720] [HTML5LOG] ReSTCBL ::: Request started::{"id":"144: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2075: [08/28 18:08:24:393] [HTML5LOG] ReSTCBL ::: Request started::{"id":"145: POST https://:@localdomain:14480/_replicate"}
Line 2084:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2097:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2105:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2113:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2121:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2375: [08/28 18:09:22:718] [HTML5LOG] ReSTCBL ::: Request started::{"id":"146: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2423: [08/28 18:13:25:463] [HTML5LOG] ReSTCBL ::: Request started::{"id":"147: POST https://:@localdomain:14480/_replicate"}
Line 2425: [08/28 18:14:22:733] [HTML5LOG] ReSTCBL ::: Request started::{"id":"148: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2429:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2464: [08/28 18:18:26:561] [HTML5LOG] ReSTCBL ::: Request started::{"id":"149: POST https://:@localdomain:14480/_replicate"}
Line 2466: [08/28 18:19:22:744] [HTML5LOG] ReSTCBL ::: Request started::{"id":"150: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2469: [08/28 18:20:04:296] [HTML5LOG] ReSTCBL ::: Request started::{"id":"151: POST https://:@localdomain:14480/data/_compact"}
Line 2502: [08/28 18:23:27:621] [HTML5LOG] ReSTCBL ::: Request started::{"id":"152: POST https://:@localdomain:14480/_replicate"}
Line 2504: [08/28 18:24:22:756] [HTML5LOG] ReSTCBL ::: Request started::{"id":"153: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2516: [08/28 18:29:22:768] [HTML5LOG] ReSTCBL ::: Request started::{"id":"154: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2526: [08/28 18:33:06:878] [HTML5LOG] ReSTCBL ::: Request started::{"id":"155: GET https://:@localdomain:14480/_active_tasks"}
Line 2528: [08/28 18:34:22:768] [HTML5LOG] ReSTCBL ::: Request started::{"id":"156: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}
Line 2549: [08/28 18:37:02:654] [HTML5LOG] ReSTCBL ::: Request started::{"id":"157: POST https://:@localdomain:14480/_replicate"}
Line 2553:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2566:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false
Line 2843: [08/28 18:37:28:147] [HTML5LOG] ReSTCBL ::: Request started::{"id":"158: GET https://:@localdomain:14480/data/s919480109390_ptx1503925648131_meta.doc"}
Line 2901:  History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false

App Webview

Line 42946: [08/28 17:54:22:697] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43015: [08/28 17:59:22:710] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43090: [08/28 18:04:22:736] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43145: [08/28 18:08:24:400] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43158: [08/28 18:08:25:491] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43161: [08/28 18:08:27:061] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43164: [08/28 18:08:28:078] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43167: [08/28 18:08:29:073] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43170: [08/28 18:08:32:186] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43343: [08/28 18:09:22:721] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43427: [08/28 18:13:25:467] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43429: [08/28 18:14:22:744] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43432: [08/28 18:14:31:067] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43462: [08/28 18:18:26:572] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43464: [08/28 18:19:22:755] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43478: [08/28 18:20:04:301] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43552: [08/28 18:23:27:633] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43554: [08/28 18:24:22:763] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43585: [08/28 18:29:22:777] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43647: [08/28 18:33:06:890] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43676: [08/28 18:34:22:771] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43735: [08/28 18:37:02:657] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43738: [08/28 18:37:03:966] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43741: [08/28 18:37:05:674] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43830: [08/28 18:37:28:150] WhitelistPlugin ---------- CBL URL allowed to Navigate -----
Line 43856: [08/28 18:37:36:267] WhitelistPlugin ---------- CBL URL allowed to Navigate -----

3

Couchbase Logs:

Do not see any request hitting the server.

Detail Logs:

App JS:
https://gist.github.com/NitzDKoder/a4562f511329919caa44acbe5bee7d47

App Webview
https://gist.github.com/NitzDKoder/f2ceed30c41f6bfa8a2127bbbde06195

Couchbase Logs:
https://gist.github.com/NitzDKoder/d23918d3b9af9860ea4e6c0ccad2bc45

@hideki @pasin please share you thoughts..

Thanks
Nithin

[hideki]

Hi @NitzDKoder,

Once you encounter this problem, can you try to access Listener URL from the phone browser?
If accessible, the problem could be in the WebView.
If not, Listener's server socket becomes a bad state.

[NitzDKoder]

@hideki what problem you suspect in webview ? the request is successfully allowed at webview level at whitelistplugin level..

https://github.com/apache/cordova-plugin-whitelist

Will check and confirm if its accessible from browser.

[NitzDKoder]

@hideki

Browser level request work as below:

Line 18577: 08-29 13:03:21.741 W/System.err( 9734): [08/29 01:03:21.751] [62] Listener: [REQUEST] (Acme.Utils.ThreadPool(7)-PooledThread: Acme.Serve.Serve$ServeConnection@2dcf3879) GET: https://localdomain:51625/data/s919480109390_ptx1503987993647_meta.doc
Line 24261: 08-29 13:03:42.751 W/System.err( 9734): [08/29 01:03:42.755] [61] Listener: [REQUEST] (Acme.Utils.ThreadPool(6)-PooledThread: Acme.Serve.Serve$ServeConnection@b14f16c) GET: https://localdomain:51625/data/s919480109390_ptx1503987993647_meta.doc
Line 53335: 08-29 13:16:19.311 W/System.err( 9734): [08/29 01:16:19.320] [62] Listener: [REQUEST] (Acme.Utils.ThreadPool(7)-PooledThread: Acme.Serve.Serve$ServeConnection@110843ed) GET: https://localdomain:51625/data/s919480109390_ptx1503987993647_meta.doc

App requests fails to reach local server:

1) 08-29 13:16:22.611 D/HTML5LOG: cblPtxInterface.syncManager()-> doStartPost()-> Start Sync = {"source":"data","target":{"url":"https://AAAAAAAAAAAA:XXXXXXXXXXXXXXXXX@mydomain/data/data"},"continuous":true,"filter":"pushfilter/bystate"}

08-29 13:16:22.611 D/HTML5LOG: cblPtxInterface.syncManager()-> doStartPost()-> Start Sync for PUSH

08-29 13:16:22.611 D/HTML5LOG: ReSTCBL ::: Request started::{"id":"93: POST https://:@localdomain:51625/_replicate"}

08-29 13:16:22.611 D/WhitelistPlugin( 9734): ---------- cblURL: https://:@localdomain:51625/

08-29 13:16:22.611 D/WhitelistPlugin( 9734): ---------- CBL URL allowed to Navigate -----

2) 08-29 13:16:25.211 D/HTML5LOG: UI.Util.setHistProxy ----> threadId = %22tel%3A%2B919663733552%22

08-29 13:16:25.211 D/HTML5LOG: History url = https://:@localdomain:51625/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false

08-29 13:16:25.441 D/WhitelistPlugin( 9734): ---------- cblURL: https://:@localdomain:51625/

08-29 13:16:25.441 D/WhitelistPlugin( 9734): ---------- CBL URL allowed to Navigate -----

3) 08-29 13:16:43.321 D/HTML5LOG: ReSTCBL ::change opts : PTX timeout

08-29 13:16:43.341 D/HTML5LOG: ReSTCBL ::: Request started::{"id":"94: GET https://:@localdomain:51625/data/_changes?since=106&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}

08-29 13:16:43.351 D/WhitelistPlugin( 9734): ---------- cblURL: https://:@localdomain:51625/

08-29 13:16:43.351 D/WhitelistPlugin( 9734): ---------- CBL URL allowed to Navigate -----

Detail Logs:
ADB:
https://gist.github.com/NitzDKoder/e3453adaf8cd588fc70864cbfde07b98

CBL Logs:

https://gist.github.com/NitzDKoder/6b8b7c7a1bed27f07a186a05b44bb29a

Thanks
Nithin

[hideki]

It seems JavaScript REST API calls from WebView can not reach to Listener. I guess the issue is in WebView. You could also test to access the internet (such as www.google.com) from JavaScript once this error occurs. We could narrow down further.

[NitzDKoder]

@hideki
The www.google.com works when the issue happens..able to navigate within our webview..
More observation:
a)Issue not seen when webview is downgraded and used stock webview v35 with 5 mins heartbeat.
b)Issue not seen in latest webview with 1 min changes timeout at router.java.

[NitzDKoder]

@hideki issue seen in above b) as well..
How stable is https://github.com/couchbaselabs/TodoLite-PhoneGap/blob/f1a810f9408a9807f3bf25ae69ba1d6a6aaee71c/js/modules.js

This module?

As the request works from browser..can we suspect problem in this .js??

[hideki]

@NitzDKoder,
I am sorry I am not expert of JavaScript and also modules.js including its underling libraries.
I guess a problem could be in the particular version of Android API, PhoneGap (Cordova) library, or JavaScript codes. However, I can not identify the problem based on current information.

[NitzDKoder]

@hideki

1. we control remote replication by REST via listener
   Ex: Stop a continuous replication.

Stop Sync = {"target":"ptxdata","source":{"url":"https://AAAAAAAAAAAA:XXXXXXXXXXXXXXXXX@mydomain/data"},"continuous":true,"filter":"sync_gateway/bychannel","query_params":{"channels":"PTX-919480109390-meta-CH,919480109390-CH"}}
[08/28 17:40:08:013] [HTML5LOG] ReSTCBL ::: Request started::{"id":"139: POST https://:@localdomain:14480/_replicate"}

2. also listen to local db changes by REST via listener
   Ex: longpoll _changes.

Line 2050: [08/28 17:54:22:685] [HTML5LOG] ReSTCBL ::: Request started::{"id":"142: GET https://:@localdomain:14480/data/_changes?since=97&include_docs=true&style=main_only&heartbeat=300000&feed=longpoll"}

3. local database view query done using REST request via listener.
   Ex: view query.

Line 2553: History url = https://:@localdomain:14480/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919663733552%22&reduce=false&group=false

All the request fail sometimes on network tranistions.
We see some exception serve.java.(socket closed, socket timeout and broken pipe.)

Line 38690: [09/19 16:29:44:748] [13043] Listener: Serve Run parseRequest IOException Socket[address=localhost/localdomain,port=57987,localPort=24089]
Line 38691: [09/19 16:29:44:748] [13043] Listener: Serve Run parseRequest IOException
Line 38692: [09/19 16:29:44:749] [13043] Listener: Serve Run parseRequest SocketTimeoutException Socket[address=localhost/localdomain,port=57987,localPort=24089]
Line 38693: [09/19 16:29:44:750] [13043] Listener: Serve Run parseRequest SocketTimeoutException

[09/19 13:07:30:338] [5415] Listener: Serve Run parseRequest Exception socket Socket[address=localhost/localdomain,port=35280,localPort=41283]
[09/19 13:07:30:339] [5415] Listener: TJWS: IO error: javax.net.ssl.SSLException: Write error: ssl=0x94cba400: I/O error during system call, Broken pipe in processing a request /ptxdata/_changes from localhost/localdomain:41283 / com.android.org.conscrypt.OpenSSLSocketImpl
[09/19 13:07:30:339] [5415] Listener: Serve Run parseRequest Exception Write error: ssl=0x94cba400: I/O error during system call, Broken pipe

https://github.com/couchbase/couchbase-lite-java-listener/blob/master/vendor/tjws/src/java/Acme/Serve/Serve.java#L2130

Workaround:
Currently restarting listener on some request failures.

TODO:
Understand how the client socket is behaving network transitions.Is the sever socket stable network transitions.Maybe android invalidates all sockets.

Will update more..

Thanks
Nithin

[hideki]

Hi @NitzDKoder,

I have tried to reproduce this issue with Todo PhoneGap sample. So far, I could not reproduce this issue. I am using Nexus 6 with Android 7.1.1.

How is your test environment?

Thanks,
Hideki

[hideki]

Hi @NitzDKoder,

I have another question.

How can I create the state of idle the rest request?

After idle the REST request from HTML/JS fails to get response from server.