BotSession.stop() takes a long time

[stefan-reich]

...about 30 seconds I'd say. No exception, and it seems to do its job eventually. What's going on there? It's a long-poll bot, I'm using version 3.6.

PS: AI bot coming up.

Many greetings, Stefan

[UnAfraid]

Measure it with some profiler check whats causing the delay, from first glance i didn't see anything suspicious JProfiler / Yourkit

[stefan-reich]

Yeah I should do that, thanks

[marcokrikke]

I'm having a similar issue when using a LongPollingBot.

When shutting down the application, a Spring Boot @PreDestroy annotated method is called, which in turn calls stop()on the BotSession. Then nothing happens, until the Telegram API responds with a HTTP response.

Please find below the relevant logs and a thread dump.

2018-09-12 14:29:42.947 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "POST /botxxxxxxx/getupdates HTTP/1.1[\r][\n]"
2018-09-12 14:29:42.947 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "charset: UTF-8[\r][\n]"
2018-09-12 14:29:42.947 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Content-Length: 59[\r][\n]"
2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Content-Type: application/json; charset=UTF-8[\r][\n]"
2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Host: api.telegram.org[\r][\n]"
2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]"
2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_172)[\r][\n]"
2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]"
2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "[\r][\n]"
2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "{"offset":1,"limit":100,"timeout":50,"method":"getupdates"}"
2018-09-12 14:29:43.444  INFO 27157 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2018-09-12 14:29:43.449  INFO 27157 --- [           main] n.e.a.o.s.Application                    : Started Application in 3.728 seconds (JVM running for 4.4)
2018-09-12 14:30:32.954 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
2018-09-12 14:30:32.954 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Server: nginx/1.12.2[\r][\n]"
2018-09-12 14:30:32.954 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Date: Wed, 12 Sep 2018 12:30:32 GMT[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Content-Type: application/json[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Content-Length: 23[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Connection: keep-alive[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Access-Control-Allow-Origin: *[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Access-Control-Allow-Methods: GET, POST, OPTIONS[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Strict-Transport-Security: max-age=31536000; includeSubdomains[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "[\r][\n]"
2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "{"ok":true,"result":[]}"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "POST /botxxxxxxx/getupdates HTTP/1.1[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "charset: UTF-8[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Content-Length: 59[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Content-Type: application/json; charset=UTF-8[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Host: api.telegram.org[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_172)[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "[\r][\n]"
2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 >> "{"offset":1,"limit":100,"timeout":50,"method":"getupdates"}"
2018-09-12 14:30:40.166  INFO 27157 --- [      Thread-13] ConfigServletWebServerApplicationContext : Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@ba2f4ec: startup date [Wed Sep 12 14:29:40 CEST 2018]; root of context hierarchy
2018-09-12 14:30:40.168  INFO 27157 --- [      Thread-13] o.s.j.e.a.AnnotationMBeanExporter        : Unregistering JMX-exposed beans on shutdown
2018-09-12 14:30:40.169 DEBUG 27157 --- [      Thread-13] .TelegramLongPollingBotAutoConfiguration : Stopping Telegram bot session, wait a log time for a response from the Telegram API
2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Server: nginx/1.12.2[\r][\n]"
2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Date: Wed, 12 Sep 2018 12:31:23 GMT[\r][\n]"
2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Content-Type: application/json[\r][\n]"
2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Content-Length: 23[\r][\n]"
2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Connection: keep-alive[\r][\n]"
2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Access-Control-Allow-Origin: *[\r][\n]"
2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Access-Control-Allow-Methods: GET, POST, OPTIONS[\r][\n]"
2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection[\r][\n]"
2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "Strict-Transport-Security: max-age=31536000; includeSubdomains[\r][\n]"
2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "[\r][\n]"
2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire                     : http-outgoing-1 << "{"ok":true,"result":[]}"

Process finished with exit code 130 (interrupted by signal 2: SIGINT)

"Thread-13" #50 prio=5 os_prio=31 tid=0x00007ff4951dd000 nid=0x8807 waiting for monitor entry [0x000070000f2f2000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.telegram.telegrambots.updatesreceivers.DefaultBotSession.stop(DefaultBotSession.java:81)
        - waiting to lock <0x0000000773cdb9e0> (a org.telegram.telegrambots.updatesreceivers.DefaultBotSession)
        at xxx.telegram.config.TelegramLongPollingBotAutoConfiguration.lambda$stop$1(TelegramLongPollingBotAutoConfiguration.java:59)
        at xxx.telegram.config.TelegramLongPollingBotAutoConfiguration$$Lambda$381/1025717200.accept(Unknown Source)
        at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382)
        at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580)
        at xxx.telegram.config.TelegramLongPollingBotAutoConfiguration.stop(TelegramLongPollingBotAutoConfiguration.java:56)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:366)
        at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeDestroyMethods(InitDestroyAnnotationBeanPostProcessor.java:324)
        at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeDestruction(InitDestroyAnnotationBeanPostProcessor.java:156)
        at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:240)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:954)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:961)
        at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1041)
        at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1017)
        at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:937)
        - locked <0x00000006c001fd10> (a java.lang.Object)

   Locked ownable synchronizers:
        - None

"TestBot Telegram Connection" #31 prio=1 os_prio=31 tid=0x00007ff495a20000 nid=0xa10b runnable [0x000070000dcb0000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
        at sun.security.ssl.InputRecord.read(InputRecord.java:503)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
        - locked <0x0000000773d27410> (a java.lang.Object)
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
        - locked <0x0000000773d26f00> (a sun.security.ssl.AppInputStream)
        at org.apache.http.impl.conn.LoggingInputStream.read(LoggingInputStream.java:84)
        at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
        at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
        at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282)
        at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
        at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
        at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
        at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
        at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165)
        at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
        at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
        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:110)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
        at org.telegram.telegrambots.updatesreceivers.DefaultBotSession$ReaderThread.getUpdatesFromServer(DefaultBotSession.java:244)
        at org.telegram.telegrambots.updatesreceivers.DefaultBotSession$ReaderThread$$Lambda$331/448782465.getUpdates(Unknown Source)
        at org.telegram.telegrambots.updatesreceivers.DefaultBotSession$ReaderThread.run(DefaultBotSession.java:185)
        - locked <0x0000000773cdb9e0> (a org.telegram.telegrambots.updatesreceivers.DefaultBotSession)

   Locked ownable synchronizers:
        - None

[stefan-reich]

I also profiled and saw nothing but a sleeping stop() method. Maybe Telegram API lets us wait?

Marco Krikke [email protected] schrieb am Mi., 12. Sep. 2018 14:48:

I'm having a similar issue when using a LongPollingBot.

When shutting down the application, a Spring Boot @PreDestroy annotated method is called, which in turn calls stop()on the BotSession. Then nothing happens, until the Telegram API responds with a HTTP response.

Please find below the relevant logs and a thread dump.

2018-09-12 14:29:42.947 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "POST /botxxxxxxx/getupdates HTTP/1.1[\r][\n]" 2018-09-12 14:29:42.947 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "charset: UTF-8[\r][\n]" 2018-09-12 14:29:42.947 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Content-Length: 59[\r][\n]" 2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Content-Type: application/json; charset=UTF-8[\r][\n]" 2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Host: api.telegram.org[\r][\n]" 2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]" 2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_172)[\r][\n]" 2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]" 2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "[\r][\n]" 2018-09-12 14:29:42.948 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "{"offset":1,"limit":100,"timeout":50,"method":"getupdates"}" 2018-09-12 14:29:43.444 INFO 27157 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path '' 2018-09-12 14:29:43.449 INFO 27157 --- [ main] n.e.a.o.s.Application : Started Application in 3.728 seconds (JVM running for 4.4) 2018-09-12 14:30:32.954 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]" 2018-09-12 14:30:32.954 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Server: nginx/1.12.2[\r][\n]" 2018-09-12 14:30:32.954 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Date: Wed, 12 Sep 2018 12:30:32 GMT[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Content-Type: application/json[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Content-Length: 23[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Connection: keep-alive[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Access-Control-Allow-Origin: *[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Access-Control-Allow-Methods: GET, POST, OPTIONS[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Strict-Transport-Security: max-age=31536000; includeSubdomains[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "[\r][\n]" 2018-09-12 14:30:32.955 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "{"ok":true,"result":[]}" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "POST /botxxxxxxx/getupdates HTTP/1.1[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "charset: UTF-8[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Content-Length: 59[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Content-Type: application/json; charset=UTF-8[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Host: api.telegram.org[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_172)[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "[\r][\n]" 2018-09-12 14:30:33.504 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 >> "{"offset":1,"limit":100,"timeout":50,"method":"getupdates"}" 2018-09-12 14:30:40.166 INFO 27157 --- [ Thread-13] ConfigServletWebServerApplicationContext : Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@ba2f4ec: startup date [Wed Sep 12 14:29:40 CEST 2018]; root of context hierarchy 2018-09-12 14:30:40.168 INFO 27157 --- [ Thread-13] o.s.j.e.a.AnnotationMBeanExporter : Unregistering JMX-exposed beans on shutdown 2018-09-12 14:30:40.169 DEBUG 27157 --- [ Thread-13] .TelegramLongPollingBotAutoConfiguration : Stopping Telegram bot session, wait a log time for a response from the Telegram API 2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]" 2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Server: nginx/1.12.2[\r][\n]" 2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Date: Wed, 12 Sep 2018 12:31:23 GMT[\r][\n]" 2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Content-Type: application/json[\r][\n]" 2018-09-12 14:31:23.510 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Content-Length: 23[\r][\n]" 2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Connection: keep-alive[\r][\n]" 2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Access-Control-Allow-Origin: *[\r][\n]" 2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Access-Control-Allow-Methods: GET, POST, OPTIONS[\r][\n]" 2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Access-Control-Expose-Headers: Content-Length,Content-Type,Date,Server,Connection[\r][\n]" 2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "Strict-Transport-Security: max-age=31536000; includeSubdomains[\r][\n]" 2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "[\r][\n]" 2018-09-12 14:31:23.511 DEBUG 27157 --- [gram Connection] org.apache.http.wire : http-outgoing-1 << "{"ok":true,"result":[]}"

Process finished with exit code 130 (interrupted by signal 2: SIGINT)

"Thread-13" #50 prio=5 os_prio=31 tid=0x00007ff4951dd000 nid=0x8807 waiting for monitor entry [0x000070000f2f2000] java.lang.Thread.State: BLOCKED (on object monitor) at org.telegram.telegrambots.updatesreceivers.DefaultBotSession.stop(DefaultBotSession.java:81) - waiting to lock <0x0000000773cdb9e0> (a org.telegram.telegrambots.updatesreceivers.DefaultBotSession) at xxx.telegram.config.TelegramLongPollingBotAutoConfiguration.lambda$stop$1(TelegramLongPollingBotAutoConfiguration.java:59) at xxx.telegram.config.TelegramLongPollingBotAutoConfiguration$$Lambda$381/1025717200.accept(Unknown Source) at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382) at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580) at xxx.telegram.config.TelegramLongPollingBotAutoConfiguration.stop(TelegramLongPollingBotAutoConfiguration.java:56) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement.invoke(InitDestroyAnnotationBeanPostProcessor.java:366) at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeDestroyMethods(InitDestroyAnnotationBeanPostProcessor.java:324) at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeDestruction(InitDestroyAnnotationBeanPostProcessor.java:156) at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:240) at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571) at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543) at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:954) at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504) at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:961) at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1041) at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1017) at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:937) - locked <0x00000006c001fd10> (a java.lang.Object)

Locked ownable synchronizers: - None

"TestBot Telegram Connection" #31 prio=1 os_prio=31 tid=0x00007ff495a20000 nid=0xa10b runnable [0x000070000dcb0000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) at sun.security.ssl.InputRecord.read(InputRecord.java:503) at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983) - locked <0x0000000773d27410> (a java.lang.Object) at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940) at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) - locked <0x0000000773d26f00> (a sun.security.ssl.AppInputStream) at org.apache.http.impl.conn.LoggingInputStream.read(LoggingInputStream.java:84) at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137) at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153) at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282) at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138) at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) 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:110) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.telegram.telegrambots.updatesreceivers.DefaultBotSession$ReaderThread.getUpdatesFromServer(DefaultBotSession.java:244) at org.telegram.telegrambots.updatesreceivers.DefaultBotSession$ReaderThread$$Lambda$331/448782465.getUpdates(Unknown Source) at org.telegram.telegrambots.updatesreceivers.DefaultBotSession$ReaderThread.run(DefaultBotSession.java:185) - locked <0x0000000773cdb9e0> (a org.telegram.telegrambots.updatesreceivers.DefaultBotSession)

Locked ownable synchronizers: - None

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/rubenlagus/TelegramBots/issues/498#issuecomment-420635512, or mute the thread https://github.com/notifications/unsubscribe-auth/AET6Q-uGNckLIeJhYNkIAIKn6MeB_nZIks5uaQKugaJpZM4VksfE .

[marcokrikke]

It does @stefan-reich. A POST request is sent to the Telegram API, including a 50 second timeout parameter (see log). The Telegram API responds when new data is available, or with an empty result after 50 seconds have passed.

[stefan-reich]

So it is a bug, right?

Marco Krikke [email protected] schrieb am Mi., 12. Sep. 2018 15:21:

It does @stefan-reich https://github.com/stefan-reich. A POST request is sent to the Telegram API, including a 50 second timeout parameter (see log). The Telegram API responds when new data is available, or with an empty result after 50 seconds have passed.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/rubenlagus/TelegramBots/issues/498#issuecomment-420645675, or mute the thread https://github.com/notifications/unsubscribe-auth/AET6Q1KRmNBWzyqGp3ZTdjHVJmKfLdcdks5uaQpzgaJpZM4VksfE .

[marcokrikke]

I haven't looked into it in that much detail, but it sounds like some lock that blocks the stop() method until a response from the Telegram API has been received.

[rubenlagus]

Stop method should be waiting until current request is executed and then stop the process. This way the connection is correctly closed before actually stopping the bot itself.

[marcokrikke]

Ok, so this is intentional behaviour, right @rubenlagus ? Perhaps good to document this in the README?

[s0ullight]

Similarly, BotSession.isRunning() takes 50 seconds to return a boolean value. I had to work around this by having a thread regularly check it and modify a static boolean. I agree that it should be documented that these methods take considerable amounts of time to complete, as they could jeopardize time critical operations.

[avently]

I spent days half year ago trying to figure out whats wrong with my code and why bot is not stopping and why I have multiple bots when trying to restart it. It should be wrote in the wiki or readme.

[ZzetT]

I run into the same issue and I'm glad that I found this thread. Is there really no better solution that can be implemented for the TelegramBot itself? I can't imagine that any develeper expects that a simple method only returning a boolean variable takes so much time.

[rubenlagus]

I've changed the method and should be faster from next version

[mirfatif]

With v5.7.1 it still takes up to 30+ seconds.

[Remigio07]

Still taking ~45 s on 6.8.0.