Projects tigase _server tigase-http-api Issues #87
"request accept time exceeded" for every request when using `JavaStandaloneHttpServer` (#87)
Closed
wojciech.kapcia@tigase.net opened 4 years ago

Execute any simple call to REST API (for example those from https://projects.tigase.net/issue/helpdeskpr-546#focus=streamItem-4-26369.0-0):

$ curl -vv -u admin@atlantiscity:admin -H "Content-Type: application/xml"  -X PUT --data-ascii '<user><password>tigase</password></user>' http://atlantiscity.local:8080/rest/user/tigase@atlantiscity

And it will result in WARNING in the logs, even though the connection is closed correctly

[2020-06-24 16:25:25:744] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 18
[2020-06-24 16:25:48:552] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 20
[2020-06-24 16:26:39:123] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 22
[2020-06-24 16:27:27:967] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 29
[2020-06-24 16:27:27:967] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 30
[2020-06-24 16:27:27:968] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 31
[2020-06-24 16:27:32:732] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 33
[2020-06-24 16:27:50:994] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 36
[2020-06-24 16:27:50:994] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 37
[2020-06-24 16:28:08:004] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 39
[2020-06-24 16:28:27:925] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 42
[2020-06-24 16:28:37:399] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 45
[2020-06-24 16:28:37:399] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 46
[2020-06-24 16:28:37:803] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 47
[2020-06-24 16:29:12:344] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 50
[2020-06-24 16:29:12:345] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 51
[2020-06-24 16:29:15:801] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 53
[2020-06-24 16:29:37:809] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 55
[2020-06-24 16:31:23:778] [WARNING ] [      pool-16-thread-1 ] JavaStandaloneHttpServer$ExecutorWithTimeout$Timer.lambda$0(): request accept time exceeded! for id = 59

I think we should fix the timer, or at least don't print it with WARNING…

Andrzej Wójcik (Tigase) commented 4 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)
wojciech.kapcia@tigase.net commented 4 years ago

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 admin

Also 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
Andrzej Wójcik (Tigase) commented 4 years ago

@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 not async).

wojciech.kapcia@tigase.net commented 4 years ago

Nope. I just started fresh copy of Tigase, pasted:

GET http://atlantiscity.local:8080/rest/adhoc/vhost-man@atlantiscity
Authorization: Basic admin@atlantiscity admin

in 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 bytes

And 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 = 2

What's curious is the id = 2 - the code tigase.http.java.JavaStandaloneHttpServer.ExecutorWithTimeout#counter has private 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)

tigase.log.0

Andrzej Wójcik (Tigase) commented 4 years ago

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.

issue 1 of 1
Type
Bug
Priority
Minor
Assignee
Version
tigase-server-8.1.0
Issue Votes (0)
Watchers (0)
Reference
tigase/_server/tigase-http-api#87
Please wait...
Page is in error, reload to recover