Understanding the log files

I have a project with ESP8266 + local server and every 29 minutes the hardware is reconnecting to the server.
I have reviewed and tested different values of the parameters of the Blynk_ver0.4.4 libraries, server v0.22.0, of my router / wifi, but I have not been able to find the source of the problem.
Perhaps understanding the files in detail, I can find some explanation.
Where can you find detailed documentation of the files “stats.log”, “worker.log”, “postgres.log”, “blynk.log”, “netty.log”
regards

I normally look at blynk.log.

Are the disconnects exactly at 29 minute intervals?

The logs might help but you should perhaps use full debugging in your ESP sketch to locate the problem.

hello Costas,
Here I send a short summary of the interval of the file “blynk.log”
Normally the ESP remains on for about 10 minutes, and then disconnects and reconnects at 19 minutes, which gives a full cycle between reconnections of 29 minutes.
Currently I am suspected of having a problem with my route / wifi.
In the file “stats.log” I have seen many values that I do not understand in detail, and maybe they would help me.
Is there no detailed documentation about this log?

2017-01-30 16:24:08.351 INFO - Hardware plain tcp/ip server listening at 8442 port.
2017-01-30 16:24:08.521 INFO - Hardware SSL server listening at 8441 port.
2017-01-30 16:24:08.652 INFO - Application server listening at 8443 port.
2017-01-30 16:24:08.782 INFO - HTTP API server listening at 8080 port.
2017-01-30 16:24:08.982 INFO - HTTPS API server listening at 9443 port.
2017-01-30 16:24:09.132 INFO - HTTPS Admin UI server listening at 7443 port.
2017-01-30 16:24:09.272 INFO - Web Sockets server listening at 8082 port.
2017-01-30 16:24:09.493 INFO - Web SSL Sockets server listening at 8081 port.
2017-01-30 16:24:09.663 INFO - Mqtt hardware server listening at 8440 port.
2017-01-30 16:33:33.814 INFO - “My mail access server” hardware joined.
2017-01-30 17:02:55.157 INFO - “My mail access server” hardware joined.
2017-01-30 17:32:02.029 INFO - “My mail access server” hardware joined.
2017-01-30 18:01:10.833 INFO - “My mail access server” hardware joined.
2017-01-30 18:30:26.107 INFO - “My mail access server” hardware joined.
2017-01-30 18:59:43.084 INFO - “My mail access server” hardware joined.
2017-01-30 19:29:05.628 INFO - “My mail access server” hardware joined.
2017-01-30 19:58:02.936 INFO - “My mail access server” hardware joined.
2017-01-30 20:27:20.974 INFO - “My mail access server” hardware joined.
2017-01-30 20:56:23.931 INFO - “My mail access server” hardware joined.
2017-01-30 21:25:39.124 INFO - “My mail access server” hardware joined.
2017-01-30 21:55:00.778 INFO - “My mail access server” hardware joined.
2017-01-30 22:24:22.210 INFO - “My mail access server” hardware joined.
2017-01-30 22:53:43.032 INFO - “My mail access server” hardware joined.
2017-01-30 23:23:00.389 INFO - “My mail access server” hardware joined.
2017-01-30 23:52:13.009 INFO - “My mail access server” hardware joined.

Me too or buggy code.

In server.properties you can change the log verbosity. Set it to maximum logging, for now, which if I’m not mistaken is “trace” from a default of info / error. I currently have mine set to debug.

Hi Costas,
I made a capture for 93 minutes with the “DEBUG” mode on.
But the result is a “blynk.log” file that has a size of 1.2 MB and 15,209 records / lines.
Is it possible to share it in any way?
I I do not know java, but I think the following lines are the most representative:

2017-01-31 13: 47: 40,760 INFO - Using data dir ‘. \ Users’
2017-01-31 13: 47: 41,010 DEBUG - Starting reading user DB.
2017-01-31 13: 48: 11.434 DEBUG - Reading user DB finished.
INFO - Region: location 2017-01-31 13: 48: 11.434
2017-01-31 13: 48: 45,042 DEBUG - Closed 0 connections out of 0 in 10 ms
2017-01-31 13: 48: 46,053 DEBUG - Closed 0 connections out of 0 in 0 ms
*
*
2017-01-31 13: 50: 11,086 DEBUG - Blynk server IOException.
Java.io.IOException: Interruption of an existing connection by the remote host
At sun.nio.ch.SocketDispatcher.read0 (Native Method) ~ [?: 1.8.0_121]
At sun.nio.ch.SocketDispatcher.read (Unknown Source) ~ [?: 1.8.0_121]
At sun.nio.ch.IOUtil.readIntoNativeBuffer (Unknown Source) ~ [?: 1.8.0_121]
At sun.nio.ch.IOUtil.read (Unknown Source) ~ [?: 1.8.0_121]
At sun.nio.ch.SocketChannelImpl.read (Unknown Source) ~ [?: 1.8.0_121]
At io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes (UnpooledUnsafeDirectByteBuf.java:427) ~ [server-0.22.0.jar :?]
At io.netty.buffer.AbstractByteBuf.writeBytes (AbstractByteBuf.java:1100) ~ [server-0.22.0.jar :?]
At io.netty.channel.socket.nio.NioSocketChannel.doReadBytes (NioSocketChannel.java:367) ~ [server-0.22.0.jar :?]
At io.netty.channel.nio.AbstractNioByteChannel $ NioByteUnsafe.read (AbstractNioByteChannel.java:118) ~ [server-0.22.0.jar :?]
At io.netty.channel.nio.NioEventLoop.processSelectedKey (NioEventLoop.java:642) ~ [server-0.22.0.jar :?]
At io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized (NioEventLoop.java:565) ~ [server-0.22.0.jar :?]
At io.netty.channel.nio.NioEventLoop.processSelectedKeys (NioEventLoop.java:479) ~ [server-0.22.0.jar :?]
At io.netty.channel.nio.NioEventLoop.run (NioEventLoop.java:441) ~ [server-0.22.0.jar :?]
At io.netty.util.concurrent.SingleThreadEventExecutor $ 5.run (SingleThreadEventExecutor.java:858) ~ [server-0.22.0.jar :?]
At io.netty.util.concurrent.DefaultThreadFactory $ DefaultRunnableDecorator.run (DefaultThreadFactory.java:144) ~ [server-0.22.0.jar :?]
At java.lang.Thread.run (Unknown Source) [?: 1.8.0_121]
2017-01-31 13: 50: 11.206 DEBUG - Closed 0 connections out of 0 in 0 ms
2017-01-31 13: 50: 11,697 DEBUG - Blynk server IOException.
*
*
2017-01-31 14: 04: 09.011 INFO - “My mail access server” hardware joined.
*
*
2017-01-31 14: 33: 17.024 INFO - “My mail access server” hardware joined.
.
.
2017-01-31 15: 02: 24.246 INFO - “My mail access server” hardware joined.

Between the lines marked with a * , approximately the same messages are repeated
Is it possible to deduce the origin of the problem?
By the way, my level of English is not very good, so please excuse me

That’s why it is only set to DEBUG when you have debugging to do :slight_smile:
No the log doesn’t really tell me anything.
The [?: 1.8.0_121] references might refer to version 1.8.0 of the Arduino IDE but that is a pure guess. Which IDE version are you using.
If the log doesn’t mean anything to @Dmitriy then we need your Serial Monitor and or sketch, preferably with full Blynk debug settings (not server log debug).

This error message seems very clear to me. Remote host (esp or router) closes connection. So now you have to dig why this happens and where exactly. Adding debug to esp would help.

29 minutes seem like some timing in your esp code.

Ok thanks, I’ll investigate more about the esp / router.

By the way, about the 5482 messages that have the reference of the date and time, 4990 correspond to “DEBUG - Closed 0 connections out of 0 in 0 ms”. This is normal?
Or indicates some additional problem

That’s ok.

I have noticed that in the “blynk.log” there is a line with the following:
2017-01-31 13:48:52.943 DEBUG - hard.socket.idle.timeout = 0

Is that value of 0 correct with what I have in “server.properties” for “leave it empty for infinity timeout”?
</>
#specifies maximum period of time when hardware socket could be idle. After which
#socket will be closed due to non activity. In seconds. Default value 15 if not provided.
#leave it empty for infinity timeout
Hard.socket.idle.timeout =
</>

yes

Hello
With the latest version of local server 0.22.1, I have noticed that the file “worker.log” has records every second, and the size on the hard disk does not stop growing.
My questions are:
1.- What is the information recorded in it?
2.- How can you cancel the registration of events or unless they are with
longer intervals

Will be fixed in next version. You may turn “error” level logging to fix it right now.

1 Like

@jaggil: You mean this xx:xx:xx.xxx - Ticket widgets : 0. Time : 0 ??
It floods my worker log too (every second). My hardware currently sends comms at 5sec interval, just to note.

@Dmitriy: but my log level IS ALREADY at error

will back to 22.0 for now.

After many tests, the problem finally encountered is some kind of incompatibility between ESP8266 and the Comtrend WAP-5881 wifi router (special model for Spanish operator Iberbanda).

The solution has consisted in the purchase of a new dedicated AP for IOT connections

2 Likes

Good. Thanks for update.

Is it normal for Hardware to join so much for local server ?

01:59:45.377 INFO - tsavascii@gmail.com hardware joined.
02:15:22.439 INFO - tsavascii@gmail.com hardware joined.
05:44:21.160 INFO - tsavascii@gmail.com hardware joined.
06:52:19.539 INFO - tsavascii@gmail.com hardware joined.
08:44:33.065 INFO - tsavascii@gmail.com hardware joined.
09:04:28.816 INFO - tsavascii@gmail.com hardware joined.
10:07:09.965 INFO - tsavascii@gmail.com hardware joined.
13:01:45.991 INFO - tsavascii@gmail.com hardware joined.
13:28:48.982 INFO - tsavascii@gmail.com hardware joined.
13:37:20.654 INFO - tsavascii@gmail.com hardware joined.
16:35:28.679 INFO - tsavascii@gmail.com Blynk-app (android-22700) joined.

Do my devices lose their connection during the day?

It depends.

Yes. Every “joined message” means “Open socket”, “Send login command with auth token”.

so

log.level=info

to

log.level=trace

:roll_eyes:

keep calm and debug :cricket:

First weird log:

17:20:04.886 DEBUG- Unsecured connection attempt or not supported protocol. Channel : /108.178.16.154:33498. Reason : io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 0600e9002100.......

17:20:05.214 DEBUG- Unsecured connection attempt or not supported protocol. Channel : /108.178.16.154:34262. Reason : io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: ec00fe006a00ec00c500.........

17:20:05.823 DEBUG- Unsecured connection attempt or not supported protocol. Channel : /108.178.16.154:34846. Reason : javax.net.ssl.SSLHandshakeException: no cipher suites in common

Who is 108.178.16.154 ?

Source: whois.arin.net
IP Address: 108.178.16.154
Name: SINGLEHOP
Handle: NET-108-178-0-0-1
Registration Date: 27.02.2012
Range: 108.178.0.0-108.178.63.255
Org: SingleHop LLC
Org Handle: SL-1370
Address: 230 S. Clark St.
PO Box 415
City: Chicago
State/Province: IL
Postal Code: 60604
Country: United States

Why this ip attempt to connect my hardware ? Is it normal or not?