REST requests reaching the couchbase lite java listener only after _changes 200 ok.

[NitzDKoder]

Hi Folks,

1. App design couchbase lite java listener is thread safe? #82 and CBL 1.4 used.

[09/25 17:48:54:097] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) GET: http://127.0.0.1:19050/data/_changes?since=15729&include_docs=true&style=main_only&timeout=240000&feed=longpoll
[09/25 17:48:54:098] [9514] Listener: authHeader is null
[09/25 17:48:54:099] [9514] Listener: Not enforcing basic auth -- allowedCredentials null or empty
[09/25 17:48:54:101] [9514] Listener: serveConnection instance :Acme.Serve.Serve$ServeConnection@14511ed
[09/25 17:48:54:102] [9514] Listener: serveConnection LiteServlet socket : Socket[address=/127.0.0.1,port=35288,localPort=19050]

_changes request goes for the 4 min wait state.

Line 399: [09/25 17:51:03:529] WhitelistPlugin url: http://127.0.0.1:19050/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919480111111%22&reduce=false&group=false
Line 403: [09/25 17:51:06:224] WhitelistPlugin url: http://127.0.0.1:19050/data/_design%2FgetHistory/_view/getHistory?key=%22tel%3A%2B919480111111%22&reduce=false&group=false
Line 409: [09/25 17:51:09:088] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342069058_meta.doc
Line 413: [09/25 17:51:10:296] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342070243_meta.doc
Line 417: [09/25 17:51:11:076] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342071040_meta.doc
Line 421: [09/25 17:51:11:994] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342071964_meta.doc
Line 425: [09/25 17:51:12:949] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342072915_meta.doc
Line 429: [09/25 17:51:13:686] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342073651_meta.doc
Line 433: [09/25 17:51:14:480] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342074434_meta.doc
Line 437: [09/25 17:51:15:441] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342075403_meta.doc
Line 441: [09/25 17:51:16:304] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342076273_meta.doc
Line 445: [09/25 17:51:17:789] WhitelistPlugin url: http://127.0.0.1:19050/data/s919888880010_ptx1506342077751_meta.doc

All the next JS REST request are queued and not processed.

[09/25 17:52:54:230] [9514] Listener: [REQUESTEND] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) GET: http://127.0.0.1:19050/data/_changes?since=15729&include_docs=true&style=main_only&timeout=240000&feed=longpoll

_changes request sent 200 ok after 4 mins.

Line 103248: [09/25 17:52:54:303] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) GET: http://127.0.0.1:19050/data/s919888880010_ptx1506341932485_s919888880004_DR.doc
Line 103290: [09/25 17:52:54:467] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506341912681_s919888880004_DR.doc
Line 103337: [09/25 17:52:54:633] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) GET: http://127.0.0.1:19050/data/s919888880004_ptx1506341932485_meta.doc
Line 103379: [09/25 17:52:54:793] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) POST: http://127.0.0.1:19050/_replicate
Line 103458: [09/25 17:52:54:963] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) POST: http://127.0.0.1:19050/_replicate
Line 103535: [09/25 17:52:55:136] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) POST: http://127.0.0.1:19050/_replicate
Line 103616: [09/25 17:52:55:307] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) POST: http://127.0.0.1:19050/_replicate
Line 103691: [09/25 17:52:55:483] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) GET: http://127.0.0.1:19050/data/_local%2Fs919888880010_UnreadHistory.doc
Line 103733: [09/25 17:52:55:615] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342069058_meta.doc
Line 103788: [09/25 17:52:55:797] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342070243_meta.doc
Line 103836: [09/25 17:52:55:989] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342071040_meta.doc
Line 103883: [09/25 17:52:56:149] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342071964_meta.doc
Line 103931: [09/25 17:52:56:310] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342072915_meta.doc
Line 103978: [09/25 17:52:56:481] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342073651_meta.doc
Line 104026: [09/25 17:52:56:681] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342074434_meta.doc
Line 104074: [09/25 17:52:56:856] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342075403_meta.doc
Line 104121: [09/25 17:52:57:035] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342076273_meta.doc
Line 104169: [09/25 17:52:57:227] [9514] Listener: [REQUEST] (Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@14511ed) PUT: http://127.0.0.1:19050/data/s919888880010_ptx1506342077751_meta.doc

Later these requests are severed.

Note: Acme.Utils.ThreadPool(1) and socket port=35288 is used to serve all requests.

@hideki please share your thoughts.. is the same socket used and thread Acme.Utils.ThreadPool(1) is issue here.?

threads_report.txt

after_changes_thread_report.txt

threads_report1.txt

cbl_logs.txt

Thanks
Nithin

[NitzDKoder]

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

is this TODO from CBL guys? please confirm..

Socket socket = acceptor.accept();
// TODO consider to use ServeConnection object pool
// TODO consider req/resp objects pooling

[hideki]

@NitzDKoder it is from original codes. Not from us.

[hideki]

@NitzDKoder

I'd like to check if all threads are used. So to confirm this, could you please provide the thread-dump.

I heard the application replace the some of library to meet the your application requirements. So does it affect low level network (socket) related library?

[NitzDKoder]

@hideki thread dump is attached..

Problem is JS/html to LocalSever(local db) level.. remote syncing uses different threads right? Please confirm..

Low level network change is only for remote syncing i.e use wolfssl as opposed to android stock openssl or boringssl.

[hideki]

TinyWebserver creates a thread per a request, and the maximum number of threads is 20. If a client sends many _changes REST requests with long poll. All threads are used by theses. Thread-dump tells you if all threads are used or not. If all threads are not used, the problem is in another area.

[NitzDKoder]

@hideki from browser requests works at that time and threadpool and tjws is servable..
Here problem seems cleint using same socket for all requests.. as the changes socket is in wait State other requests are queued in webview probably..thats my suspect..
Or on same socket both _changes and other request work?

Need to say xhr request to to use new socket everytime?

[hideki]

@NitzDKoder,
XHR could have the socket pool functionality. I don't surprise if XHR could reuse the socket for same URL, host, or domain.
Can you configure this setting?

[NitzDKoder]

https://hpbn.co/xmlhttprequest/
The browser manages connection establishment, pooling, and termination.

@hideki Need to check more on this .. TJWS is cable to parse such request..??

[hideki]

@NitzDKoder

How many _changes requests does the application send to the Listener? I wonder if the app sends more than 6 requests. See the following link.
https://stackoverflow.com/questions/561046/how-many-concurrent-ajax-xmlhttprequest-requests-are-allowed-in-popular-browse

Need to check more on this .. TJWS is cable to parse such request..??

I don't understand your question means?

[NitzDKoder]

@hideki i meant if connectionpooling been used at client (browser xhr) the tjws ia cable of handing such socket.?

We make only 1 _changes ..

[hideki]

WebView (client) and Listener (server) are two different implementations. The listener can not do any special handling for client-side connection pool or any client-side special implementation.

[hideki]

It seems the issue is caused by WebView, not by CBL. I will close this ticket.