It's not an error, it's an inquiry about PING messages

[ferorted]

Dear Sir,

I've been testing your simple-tcp-server, which I find to be a fantastic piece of work. However, it appears not to handle PING messages (0xFF) sent by Teltonika devices. This causes an error and subsequent closure of the connection with the device if a normal data message arrives after a PING.

I would greatly appreciate it if you could provide me with some guidance on how to filter received PING messages. I've tried various methods after readBuffer in handleConnection, but haven't been successful.

Thank you.

[alim-zanibekov]

Hi @ferorted, thank you for your kind words!

I've created new branch named feature/tcp-server-ping where I've added handling 0xFF packets.
I currently don't have access to teltonika devices to test the changes and I can't find any useful information in teltonika docs, so I would really appreciate if you could test the changes and let me know how it goes, thank you!

[ferorted]

Hi @alim-zanibekov,
I've done a few tests with a real FMB920 device and it seems to work fine.
For your reference:

Ping every 1 min:
INFO: 2024/06/28 17:12:03 [ IP:port]: imei conected: 865648061643078
INFO: 2024/06/28 17:12:03 [865648061643078]: message: 00000000000000300801000001905f673e0001fdd01392181d4bac02d50000000000ef0603ef01f0010100034231b0430fca09002b0000010000beb3
INFO: 2024/06/28 17:13:03 [865648061643078]: received ping
INFO: 2024/06/28 17:14:03 [865648061643078]: received ping
INFO: 2024/06/28 17:14:38 [865648061643078]: message: 00000000000000320801000001905f699b7801fdd012ca181d4c3102cc007d070000fc0704ef01f0010100fc0103421035430fcf09002b0000010000a3da
INFO: 2024/06/28 17:14:46 [865648061643078]: message: 00000000000000320801000001905f69bab801fdd012fc181d4b3702d00132080000fc0704ef01f0010100fc0003421035430fc709002b00000100002603
INFO: 2024/06/28 17:15:47 [865648061643078]: received ping
INFO: 2024/06/28 17:16:47 [865648061643078]: received ping
INFO: 2024/06/28 17:17:47 [865648061643078]: received ping
INFO: 2024/06/28 17:18:00 [865648061643078]: message: 00000000000000320801000001905f6cb08801fdd01ff1181d421902cb007f060000fc0704ef01f0010100fc0103420fe4430fe409002b00000100008e96
INFO: 2024/06/28 17:19:00 [865648061643078]: received ping
INFO: 2024/06/28 17:20:00 [865648061643078]: received ping
INFO: 2024/06/28 17:21:00 [865648061643078]: received ping
INFO: 2024/06/28 17:21:58 [865648061643078]: message: 00000000000000320801000001905f70523801fdd01277181d4a9002ce0099070000fc0704ef01f0010100fc0003421457430f9c09002b000001000029fd

However, in many test I get the following error:
Ping config: 10 min.
I reboot the device and it stills on the table (but Moving status) with fix GPS and good GSM signal:

INFO: 2024/06/28 20:00:16 [IP:port]: imei conected: 865648061643078
INFO: 2024/06/28 20:00:16 [865648061643078]: message: 000000000000003008010000019060013be001fdd01e0e181d4c8402b00000000000ef0603ef01f0010100034231bc430fef09002b0000010000126b
ERROR: 2024/06/28 20:02:29 main.go:214: [865648061643078]: read error (read tcp IP:port->IP:port: wsarecv: An error occurred during the connection attempt because the connected party did not respond properly after a period of time, or The connection failed because the connected host was unable to respond.)
INFO: 2024/06/28 20:02:29 [IP:port]: disconnected, empty data from IMEI: 865648061643078

I reboot again the device. It stills on the table (but Moving status) with fix GPS and good GSM signal:

INFO: 2024/06/28 20:12:50 [IP:port]: imei conected: 865648061643078
INFO: 2024/06/28 20:12:50 [865648061643078]: message: 0000000000000030080100000190600cc50001fdd01f08181d4a5e02b20000000000ef0603ef01f0010100034231bd43101909002b00000100009f5d
ERROR: 2024/06/28 20:15:04 main.go:214: [865648061643078]: read error (read tcp IP:port->IP:port: wsarecv: An error occurred during the connection attempt because the connected party did not respond properly after a period of time, or The connection failed because the connected host was unable to respond.)
INFO: 2024/06/28 20:15:04 [IP:port]: disconnected, empty data from IMEI: 865648061643078

I reboot again the device. It stills on the table (but Moving status) with fix GPS and good GSM signal:

INFO: 2024/06/28 20:12:50 [IP:port]: imei connected: 865648061643078
INFO: 2024/06/28 20:12:50 [865648061643078]: message: 0000000000000030080100000190600cc50001fdd01f08181d4a5e02b20000000000ef0603ef01f0010100034231bd43101909002b00000100009f5d
ERROR: 2024/06/28 20:15:04 main.go:214: [865648061643078]: read error (read tcp IP:port -> IP:port: wsarecv: An error occurred during the connection attempt because the connected party did not respond properly after a period of time, or the connection failed because the connected host could not respond.)
INFO: 2024/06/28 20:15:04 [IP:port]: disconnected, empty data from IMEI: 865648061643078
INFO: 2024/06/28 20:22:52 [865648061643078]: received ping
INFO: 2024/06/28 20:32:53 [865648061643078]: received ping

Please, pay attention at 2 last lines: received ping, while device is disconnected and not reconnected. Client list does not showthe IMEI as connected.

Thank you very much.

[alim-zanibekov]

Hi @ferorted,

INFO: 2024/06/28 20:15:04 [IP:port]: disconnected, empty data from IMEI: 865648061643078

I don't see any log message that could create this line. Did you change anything related to the connection handling/closing logic? I rechecked the code and do not see a situation where, after an exception, the server continues to receive messages from the client.

I noticed that you are running this on Windows (wsarecv), I'm not very familiar with the Windows TCP stack so I can't tell if this disconnect might be caused by some default settings related to win TCP socket keepalive timeouts, or some kind of NAT.

Either way I would try to reduce the ping timeout to about 60-90s.

There is another possibility for this exception. Perhaps we should respond to PING messages, but I still can't find any information about this.

Anyway, I created a new branch feature/update-io-elements, this update mainly focuses on the I/O element parsing logic, but I updated the TCP server example, added write/read timeout configuration and refactored the client initialization to take timeouts into account. Maybe this can help

[ferorted]

Hi @alim-zanibekov, thank you so much for your interest,
Yes, in my previous tests I made some minor changes on your code, sure that was the source of errors.
As far as I know, ping don't need a response.

So, I did few new tests with your new code (running on windows, with no modifications on your code) and it seems works fine (only a weir count in client-list, please see below).

Settings:
flag.DurationVar(&readTimeout, "read-timeout", time.Minute*5, "receive timeout")
Ping interval of the FMB device: 3 minutes.

INFO: 2024/07/01 17:23:54 http server listening at 0.0.0.0:18081
INFO: 2024/07/01 17:23:54 tcp server listening at 0.0.0.0:18080
INFO: 2024/07/01 17:24:28 [90.174.54.71:21366]: connected
INFO: 2024/07/01 17:24:28 [865648061643078-90.174.54.71:21366]: imei - 865648061643078
INFO: 2024/07/01 17:24:29 [865648061643078-90.174.54.71:21366]: message: 00000000000000300801000001906ee5ac4001fdd01522181d4a0b02c9013c070000ef0603ef01f00101000342316743103109002b00000100005a4b
INFO: 2024/07/01 17:24:29 [865648061643078-90.174.54.71:21366]: decoded: {"codecId":8,"data":[{"timestampMs":1719847464000,"lng":-3.669475,"lat":40.4572683,"altitude":713,"angle":316,"event_id":239,"speed":0,"satellites":7,"priority":1,"generationType":255,"elements":[{"id":239,"value":"01"},{"id":240,"value":"01"},{"id":1,"value":"00"},{"id":66,"value":"3167"},{"id":67,"value":"1031"},{"id":9,"value":"002b"}]}]} INFO: 2024/07/01 17:24:29 [865648061643078-90.174.54.71:21366]: io elements [frame #0]: Ignition: true, Movement: true, Digital Input 1: false, External Voltage: 12.647V, Battery Voltage: 4.145V, Analog Input 1: 0.043V
INFO: 2024/07/01 17:27:29 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:30:30 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:33:30 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:36:30 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:39:31 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:42:31 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:45:31 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:48:32 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:51:32 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:54:32 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 17:57:33 [865648061643078-90.174.54.71:21366]: received ping
INFO: 2024/07/01 18:00:33 [865648061643078-90.174.54.71:21366]: received ping

It seems OK.

but if another device is connected while first device is still connected:

INFO: 2024/07/01 18:48:13 [354017118805713-127.0.0.1:50554]: message: 000000000000002b08010000016b40d9ad80010f0ea850209a69000094000012000000030147030109007301f10000601a000100003240
INFO: 2024/07/01 18:48:13 [354017118805713-127.0.0.1:50554]: decoded: {"codecId":8,"data":[{"timestampMs":1560161136000,"lng":25.2618832,"lat":54.6990336,"altitude":148,"angle":0,"event_id":0,"speed":0,"satellites":18,"priority":1,"generationType":255,"elements":[{"id":71,"value":"03"},{"id":9,"value":"0073"},{"id":241,"value":"0000601a"}]}]} INFO: 2024/07/01 18:48:13 [354017118805713-127.0.0.1:50554]: io elements [frame #0]: Dallas Temperature ID 4: 3, Analog Input 1: 0.115V, Active GSM Operator: 24602
INFO: 2024/07/01 18:48:14 [354017118805713-127.0.0.1:50554]: received ping

Then, client-list only shows one connected device :

StatusCode : 200
StatusDescription : OK
Content : {57, 48, 46, 55...}
RawContent : HTTP/1.1 200 OK
Content-Length: 553
Content-Type: application/octet-stream
Date: Mon, 01 Jul 2024 16:51:12 GMT

                90.75.20.223:21811 - 865648061643078..................................................

Headers : {[Content-Length, 553], [Content-Type, application/octet-stream], [Date, Mon, 01 Jul 2024 16:51:12 GMT]}
RawContentLength : 553

Disconnected due timeout:
ERROR: 2024/07/01 18:58:14 main.go:230: [354017118805713-127.0.0.1:50554]: peek error (read tcp 127.0.0.1:18080->127.0.0.1:50554: i/o timeout) INFO: 2024/07/01 18:58:14 [354017118805713-127.0.0.1:50554]: client disconnected

Now, client-list shows only one, but different RawContentLength:

StatusCode : 200
StatusDescription : OK
Content : {57, 48, 46, 55...}
RawContent : HTTP/1.1 200 OK
Content-Length: 278
Content-Type: application/octet-stream
Date: Mon, 01 Jul 2024 16:58:37 GMT

                90.75.20.223:21811 - 865648061643078..................................................

Headers : {[Content-Length, 278], [Content-Type, application/octet-stream], [Date, Mon, 01 Jul 2024 16:58:37 GMT]}
RawContentLength : 278

I will continue conducted more tests and let you know.

[alim-zanibekov]

Hi @ferorted, thank you for your feedback

Then, client-list only shows one connected device

I forgot to trim the imei reading buffer

imei = strings.TrimSpace(string(buf)) // here
imei = strings.TrimSpace(string(buf[:imeiLen])) // like this

I fixed this problem (also now list-clients returns json instead of binary) and merged the latest changes from feature/update-io-elements into master.

[ferorted]

Hi again @alim-zanibekov,
Sorry, I'm very confused, because I find many things that I don't understand. Maybe I have my concepts wrong.

I'm just testing to check that the device can stay connected to the server for very long periods of time without sending data, but sending PING every 30 min. to avoid connection will be closed by GSM provider.

Then, I want to check when device loses GSM coverage and its connection, the server can detect it, and when the device has GSM coverage again, it reconnects and the server sees it.

In order not to fill this post, I attach the traces in the attached document traces.txt, of a long test. It was done with version prior your last changes about list-clients, and with following settings:
flag.DurationVar(&readTimeout, "read-timeout", time.Minute60, "receive timeout")
flag.DurationVar(&writeTimeout, "write-timeout", time.Minute2, "send timeout")
PING: every 30 min.

on it, you can see the following points:

1. (it happens several times), at first of test device connects and sends a message at 21:08:06, receives a PING at 21:38:10 and gives Peak ERR at 22:10:21 and disconnects. It seems that the PING does not reset the 60 min timer.

2. Many times a PING arrives while being Disconnected, For example: at 2:12:09 device disconnects and at 2:40:14 a PING arrives, While device is disconnected !

3. Also, please check this out (it is not in the attached document):
   INFO: 2024/07/02 19:20:04 [865648061643078-62.32.248.54:5086]: client disconnected
   My comment: GSM Coverage REMOVED in disconnected state, and server detected it:
   ERROR: 2024/07/02 19:32:41 main.go:230: [865648061643078-62.32.186.243:5551]: peek error (read tcp 192.168.1.134:18080->62.32.186.243:5551: wsarecv: An error occurred during the connection attempt as the connected party did not respond properly after a period of time, or the established connection failed as the connected host was unable to respond.)
   My comment: while it is disconnected is disconnected again:
   INFO: 2024/07/02 19:32:41 [865648061643078-62.32.186.243:5551]: client disconnected

Could it be that the connect/disconnect events are being handled or only be printed incorrectly?

Please note that there have been some connection attempts from something or someone other than a Teltonika device, and they have apparently been handled well, at 23:25:00, 1:07:52, 1:51:32, 4:13:00, 7:13:16, 10:20:20 and 10:41:13

Best regards,

[ferorted]

Now, I'm going to repeat the same test with the latest version of your code

[alim-zanibekov]

Hi @ferorted,

I'm just testing to check that the device can stay connected to the server for very long periods of time without sending data, but sending PING every 30 min. to avoid connection will be closed by GSM provider.

This is hardly possible over the Internet (only on local networks), it is better to set a reasonable ping around a couple of minutes and forget about this problem, it's only 1 byte

(it happens several times), at first of test device connects and sends a message at 21:08:06, receives a PING at 21:38:10 and gives Peak ERR at 22:10:21 and disconnects. It seems that the PING does not reset the 60 min timer.

I made a fix, but I don't know if my fix will help

Many times a PING arrives while being Disconnected, For example: at 2:12:09 device disconnects and at 2:40:14 a PING arrives, While device is disconnected!

I understood what is the problem with multiple connections, it happens because sometimes the server may not know that the connection was closed from the client side and the client connects again, here the example from your logs:

INFO: 2024/07/02 08:12:36 [865648061643078-80.251.78.54:28199]: imei - 865648061643078 // client 28199
ERROR: 2024/07/02 08:14:35 main.go:230: [865648061643078-90.169.183.112:27733]: peek error (read tcp 192.168.1.134:18080->90.169.183.112:27733: wsarecv: An error occurred during the connection attempt because the connected party did not respond appropriately after a period of time, or the established connection failed because the connected host was unable to respond.)
INFO: 2024/07/02 08:14:35 [865648061643078-90.169.183.112:27733]: client disconnected  // client 27733 (connect not included here)
INFO: 2024/07/02 08:42:40 [865648061643078-80.251.78.54:28199]: received ping 
INFO: 2024/07/02 09:12:59 [62.32.205.126:28663]: connected 
INFO: 2024/07/02 09:12:59 [865648061643078-62.32.205.126:28663]: imei - 865648061643078 // client 28663
ERROR: 2024/07/02 09:15:09 main.go:230: [865648061643078-80.251.78.54:28199]: peek error (read tcp 192.168.1.134:18080->80.251.78.54:28199: wsarecv: An error occurred during the connection attempt because the connected party did not respond appropriately after a period of time, or the established connection failed because the connected host was unable to respond.)
INFO: 2024/07/02 09:15:09 [865648061643078-80.251.78.54:28199]: client disconnected // cleint 28199
INFO: 2024/07/02 09:43:02 [865648061643078-62.32.205.126:28663]: received ping // client 28663

I've created a fix for this problem that simply closes the previous connection. (already pushed)

Also, please check this out (it is not in the attached document):
INFO: 2024/07/02 19:20:04 [865648061643078-62.32.248.54:5086]: client disconnected
My comment: GSM Coverage REMOVED in disconnected state, and server detected it:
ERROR: 2024/07/02 19:32:41 main.go:230: [865648061643078-62.32.186.243:5551]: peek error (read tcp 192.168.1.134:18080->62.32.186.243:5551: wsarecv: An error occurred during the connection attempt as the connected party did not respond properly after a period of time, or the established connection failed as the connected host was unable to respond.)
My comment: while it is disconnected is disconnected again:
INFO: 2024/07/02 19:32:41 [865648061643078-62.32.186.243:5551]: client disconnected

These are 2 different clients 62.32.248.54:5086 and 62.32.186.243:5551, the fix for 2 should help

Hope this helps

[ferorted]

Hi @alim-zanibekov and thank you dor your info.

I'm afraid this error still happen on your last code version:
Device connected -> message received -> PING received but server gives Peak ERR and disconnects.
It seems that the PING does not reset the 60 min timer.
I think the main goal of ping manage is keeping connection opened, is it right?

Setings:
flag.DurationVar(&readTimeout, "read-timeout", time.Minute60, "receive timeout")
flag.DurationVar(&writeTimeout, "write-timeout", time.Minute2, "send timeout")
PING: 30 min.

INFO: 2024/07/03 12:48:19 [145.1.189.63:8632]: connected
INFO: 2024/07/03 12:48:19 [865648061643078-145.1.189.63:8632]: imei - 865648061643078
INFO: 2024/07/03 12:48:19 [865648061643078-145.1.189.63:8632]: message: 000000000000003008010000019078358db001fdd01565181d4e7802db0106050000ef0603ef01f00101000342314a43103109002b00000100006eb2
INFO: 2024/07/03 12:48:19 [865648061643078-145.1.189.63:8632]: decoded: {"codecId":8,"data":[{"timestampMs":1720003694000,"lng":-3.6694683,"lat":40.4573816,"altitude":731,"angle":262,"event_id":239,"speed":0,"satellites":5,"priority":1,"generationType":255,"elements":[{"id":239,"value":"01"},{"id":240,"value":"01"},{"id":1,"value":"00"},{"id":66,"value":"314a"},{"id":67,"value":"1031"},{"id":9,"value":"002b"}]}]}
INFO: 2024/07/03 12:48:19 [865648061643078-145.1.189.63:8632]: io elements [frame #0]: Ignition: true, Movement: true, Digital Input 1: false, External Voltage: 12.618V, Battery Voltage: 4.145V, Analog Input 1: 0.043V
INFO: 2024/07/03 13:18:23 [865648061643078-145.1.189.63:8632]: received ping
ERROR: 2024/07/03 13:50:33 main.go:259: [865648061643078-145.1.189.63:8632]: read error (read tcp 192.168.1.134:18080->145.1.189.63:8632: wsarecv: An error occurred during the connection attempt as the connected party did not respond properly after a period of time, or the established connection failed as the connected host was unable to respond.)
INFO: 2024/07/03 13:50:33 [865648061643078-145.1.189.63:8632]: client disconnected

About "Many times a PING arrives while being Disconnected," in this first test no PING was received while client disconnected. It looks fine.

Thank you again

[alim-zanibekov]

Hi @ferorted, could you try removing all SetReadDeadline and SetWriteDeadline calls and see what happens?

[ferorted]

Hi,
With code modified as following, the result is the same as previously:

updateReadDeadline := func() bool {
/if err := conn.SetReadDeadline(time.Now().Add(r.readTimeout)); err != nil {
logger.Error.Printf("[%s]: SetReadDeadline error (%v)", logKey, err)
return false
}/
return true
}

writeWithDeadline := func(data []byte) bool {
	/*if err := conn.SetWriteDeadline(time.Now().Add(r.writeTimeout)); err != nil {
		logger.Error.Printf("[%s]: SetWriteDeadline error (%v)", logKey, err)
		return false
	}*/
	if _, err := conn.Write(data); err != nil {
		logger.Error.Printf("[%s]: error writing response (%v)", logKey, err)
		return false
	}
	// reset write deadline
	/*if err := conn.SetWriteDeadline(time.Now().Add(r.writeTimeout + r.readTimeout)); err != nil {
		logger.Error.Printf("[%s]: SetWriteDeadline error (%v)", logKey, err)
	}*/
	return true
}

It is very strange, so I will do some tests to make sure that the problem is not with the Teltonika device.

[alim-zanibekov]

Hi @ferorted, as I see connection drops within a couple of minutes since the last ping message, maybe something wrong with the sleep, open link timeout, or response timeout settings link1, link2

Can you also try adding a pong message and see if it breaks the connection or is processed normally

Something like this

if peek[0] == 0xFF { // ping packet
	if _, err = reader.Discard(1); err != nil {
		logger.Error.Printf("[%s]: reader discard error (%v)", logKey, err)
		return
	}
	logger.Info.Printf("[%s]: received ping", logKey)
+	if writeWithDeadline([]byte{0xFF}) {
+		logger.Info.Printf("[%s]: sent pong", logKey)
+	}
	continue
}

[ferorted]

Thank you very much for your great interest in helping me.
I am waiting for a response from Teltonika to a query about these disconnections.
In the meantime, I will try your suggestion and let you know the result.

[ferorted]

Hi @alim-zanibekov,
Same thing happens (at least with Ping every 10 minutes)

INFO: 2024/07/08 12:39:04 [865648061643078-90.75.99.129:31186]: io elements [frame #0]: Ignition: true, Movement: true, Digital Input 1: false, External Voltage: 12.733V, Battery Voltage: 4.093V, Analog Input 1: 0.043V
INFO: 2024/07/08 12:49:05 [865648061643078-90.75.99.129:31186]: received ping
INFO: 2024/07/08 12:49:05 [865648061643078-90.75.99.129:31186]: sent pong
INFO: 2024/07/08 12:59:07 [865648061643078-90.75.99.129:31186]: received ping
INFO: 2024/07/08 12:59:07 [865648061643078-90.75.99.129:31186]: sent pong
INFO: 2024/07/08 13:09:08 [865648061643078-90.75.99.129:31186]: received ping
INFO: 2024/07/08 13:09:08 [865648061643078-90.75.99.129:31186]: sent pong
INFO: 2024/07/08 13:19:09 [865648061643078-90.75.99.129:31186]: received ping
INFO: 2024/07/08 13:19:09 [865648061643078-90.75.99.129:31186]: sent pong
INFO: 2024/07/08 13:29:10 [865648061643078-90.75.99.129:31186]: received ping
INFO: 2024/07/08 13:29:10 [865648061643078-90.75.99.129:31186]: sent pong
ERROR: 2024/07/08 13:41:33 main.go:259: [865648061643078-90.75.99.129:31186]: read error (read tcp 192.168.1.134:18080->90.75.99.129:31186: wsarecv: An error occurred during the connection attempt as the connected party did not respond properly after a period of time, or the established connection failed as the connected host was unable to respond.)
INFO: 2024/07/08 13:41:33 [865648061643078-90.75.99.129:31186]: client disconnected
INFO: 2024/07/08 14:39:46 [145.1.144.166:32114]: connected
INFO: 2024/07/08 14:39:46 [865648061643078-145.1.144.166:32114]: imei - 865648061643078

I'm still waiting for Teltonika's reply. I'll keep you posted.

[alim-zanibekov]

Hi @ferorted, thanks for the tests!

So we know that your device is handling ping messages correctly, we can try adding pings on the server side and even try to turn off pings from the tracker side. This may work better in your case if the problem is in the tracker logic.

However, are there such problems with connection drops with 2-3 minutes pings? Are you sure it's not a network problem?