Wojciech Kapcia (Tigase) opened 5 years ago
-
@wojtek I'm not able to replicate the issue - the timer is working correctly for me. I've only got that entry when I stopped processing of the request with a debugger. Could you state JVM which is used in your case? Maybe JVM changed something and the issue is JVM specific.
In my testing I was using TTS-NG config for Tigase 8.1.0, so it used following JVM:
openjdk 12.0.1 2019-04-16 OpenJDK Runtime Environment (build 12.0.1+12) OpenJDK 64-Bit Server VM (build 12.0.1+12, mixed mode, sharing) -
I'm using rather normal configuration of the server and Java is in the following version:
openjdk version "11.0.7" 2020-04-14 OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.7+10) OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.7+10, mixed mode)From the config dump:
http (class: tigase.http.HttpMessageReceiver) {} httpServer (class: tigase.http.java.JavaStandaloneHttpServer, exportable: true) { connections (class: tigase.http.java.JavaStandaloneHttpServer$PortsConfigBean, exportable: true) { ports = [ 8080 ] 8080 (class: tigase.http.java.JavaStandaloneHttpServer$PortConfigBean) { domain = null socket = plain } } executor (class: tigase.http.java.JavaStandaloneHttpServer$ExecutorWithTimeout, exportable: true) { 'accept-timeout' = 2000 'request-timeout' = 60000 threads = 4 } }I was just working on #issue #88 and was making a lot of requests and for example (from IDEA):
GET http://atlantiscity.local:8080/rest/adhoc/vhost-man@atlantiscity Authorization: Basic admin@atlantiscity adminAlso generated a lot of entries:
[2020-06-26 20:36:41:585] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 57 [2020-06-26 20:36:56:396] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 60 [2020-06-26 20:36:56:397] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 61 [2020-06-26 20:37:03:822] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 63 [2020-06-26 20:37:09:633] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 66 [2020-06-26 20:37:09:633] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 67 [2020-06-26 20:37:18:975] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 69 -
@wojtek Were you executing multiple calls/requests at the same time? I'm asking as this timer will fire only if the request was received but not started executing in
2000ms which should not happen unless processing thread was blocked (HTTP is processed on the single thread if handlers are notasync). -
Nope. I just started fresh copy of Tigase, pasted:
GET http://atlantiscity.local:8080/rest/adhoc/vhost-man@atlantiscity Authorization: Basic admin@atlantiscity adminin idea and executed it. There result was rather normal:
GET http://atlantiscity.local:8080/rest/adhoc/vhost-man@atlantiscity HTTP/1.1 200 OK Date: Mon, 29 Jun 2020 22:31:46 GMT Transfer-encoding: chunked Content-type: application/xml <items> <item> <jid>vhost-man@atlantiscity</jid> <node>del-script</node> <name>Remove command script</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>retrieve-licence-from-server</node> <name>Force retrieving licence from the server</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>comp-repo-item-add</node> <name>Add new item</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>list-commands</node> <name>Get list available commands</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>comp-repo-item-update</node> <name>Update item configuration</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>add-script</node> <name>New command script</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>ssl-certificate-add</node> <name>Add SSL Certificate</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>comp-repo-reload</node> <name>Reload component repository</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>comp-repo-item-remove</node> <name>Remove an item</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>retrieve-code-for-licence</node> <name>Retrieve code for licence</name> </item> <item> <jid>vhost-man@atlantiscity</jid> <node>query-dns</node> <name>DNS Query</name> </item> </items> Response code: 200 (OK); Time: 447ms; Content length: 1466 bytesAnd almost immediately I saw in the logs:
[2020-06-29 18:31:51:023] [WARNING ] [ pool-13-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 2What's curious is the
id = 2- the codetigase.http.java.JavaStandaloneHttpServer.ExecutorWithTimeout#counterhasprivate AtomicInteger counter = new AtomicInteger(0);and I made 1 request.For completeness, this is my configuration:
admins = [ 'admin@atlantiscity' ] 'cm-traffic-throttling' = 'xmpp:2500:0:disc,bin:200m:0:disc' 'config-type' = 'default' debug = [ 'xmpp', 'server', 'db', 'auth', 'vhosts', 'http' ] 'default-virtual-host' = 'atlantiscity' 'hardened-mode' = relaxed dataSource () { 'pool-size' = 2 atlantiscity () { uri = 'jdbc:mysql://localhost/tigasedb_simple_install2?user=tigasedb_simple_install2&password=tigasedb_simple_install2&useSSL=false&useLegacyDatetimeCode=false&allowPublicKeyRetrieval=true&autoCreateUser=true' } default () { uri = 'jdbc:mysql://localhost/tigasedb_simple_install2?user=tigasedb_simple_install2&password=tigasedb_simple_install2&useSSL=false&useLegacyDatetimeCode=false&allowPublicKeyRetrieval=true&autoCreateUser=true' } } c2s { 'sasl-external' (active: false) {} seeOtherHost {} sslContextContainer () {} } 'dns-resolver' { 'tigase-primary-address' = 'atlantiscity.local' 'tigase-secondary-address' = 'atlantiscity.local' } http () {} logging () { 'packet-debug-full' = true handlers { 'java.util.logging.FileHandler' { append = true count = 5 level = 'ALL' limit = 50000000 pattern = 'logs/tigase.log' } } loggers { 'tigase.io.JcaTLSWrapper' { level = 'FINER' } 'tigase.io.TLSIO' { level = 'FINER' } 'tigase.net.IOService' { level = 'FINER' } } } 'message-archive' (active: false) {} monitoring (active: false) {} pubsub () { trusted = [ 'http@{clusterNode}' ] } s2s () { 'sasl-external' () { 'skip-for-domains' = [ 'pandion.im' ] } } 'sess-man' () { 'processing-in-threads' = 4 'processing-out-threads' = 4 'jabber:iq:register' () { captchaRequired = false emailRequired = true } 'jabber:iq:roster' { 'auto-authorize' = 'true' } pep (active: false) {} } stats (active: false) {}Log (with 'http' enabled) attached (with trimmed startup)
-
With IDEA I was able to replicate the issue and with increased logging found out that there are some requests that are accepted but never executed - just like connection would be established and then dropped without sending any HTTP request or data. I've added a way to cancel timer for those requests (as they just ended anyway), and that solved the issue.
| Type |
Bug
|
| Priority |
Minor
|
| Assignee | |
| Version |
tigase-server-8.1.0
|
Execute any simple call to REST API (for example those from https://projects.tigase.net/issue/helpdeskpr-546#focus=streamItem-4-26369.0-0):
And it will result in WARNING in the logs, even though the connection is closed correctly
I think we should fix the timer, or at least don't print it with WARNING…