Port 5055 choked / non responsive

takliyah4 years ago

We were testing the osmand on port 5055 along with other protocols. It was working fine for many days.

But it went offline suddenly yesterday and it did not come online till a restart.

Following is the last log it recorded. After this no more Osmand logs came.

Any help would 

2021-08-20 16:50:13  INFO: [7c8adfb8: osmand > 103.148.181.194] HEX: 485454502f312e3120323030204f4b0d0a636f6e74656e742d6c656e6774683a20300d0a0d0a
2021-08-20 16:50:13  INFO: [7c8adfb8] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
2021-08-20 16:50:13  INFO: [78ab3248] disconnected
2021-08-20 16:50:13  INFO: [29e8afad] disconnected
2021-08-20 16:50:13  INFO: [4a32fd68] disconnected
2021-08-20 16:50:13  INFO: [8f0a6950] disconnected
2021-08-20 16:50:13  INFO: [c8167564] disconnected
2021-08-20 16:50:13  INFO: [7c8adfb8] disconnected
Anton Tananaev4 years ago

Maybe you can provide some more details on the troubleshooting you did. Like, how you tested the port. Server status etc.

takliyah4 years ago

The server has 8GB of ram on amazon medium instance, 23 vehicles.
Server was running, other protocols were receiving data as usual but any request on 5055 was not responding anything.
We did not realise that it was choked for next 20 hours because web, other protocols were working as usual.
Following are also logs one device that last sent record

114942:2021-08-20 16:46:24  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:24, lat: 29.20164, lon: 79.50200, speed: 0.0, course: 335.4, accuracy: 5.5
114946:2021-08-20 16:46:25  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:25, lat: 29.20164, lon: 79.50200, course: 279.7, accuracy: 5.4
114950:2021-08-20 16:46:26  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:26, lat: 29.20164, lon: 79.50200, course: 223.2, accuracy: 5.3
114953:2021-08-20 16:46:28  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:27, lat: 29.20164, lon: 79.50200, course: 356.7, accuracy: 5.2
114956:2021-08-20 16:46:28  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:28, lat: 29.20164, lon: 79.50200, course: 168.1, accuracy: 5.2
114959:2021-08-20 16:46:29  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:29, lat: 29.20164, lon: 79.50200, course: 178.7, accuracy: 5.0
114963:2021-08-20 16:46:30  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:30, lat: 29.20164, lon: 79.50200, course: 178.8, accuracy: 5.1
114970:2021-08-20 16:46:32  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:31, lat: 29.20164, lon: 79.50200, course: 260.8, accuracy: 5.4
114985:2021-08-20 16:46:32  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:32, lat: 29.20164, lon: 79.50200, course: 268.1, accuracy: 5.5
114988:2021-08-20 16:46:33  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:33, lat: 29.20164, lon: 79.50200, speed: 0.0, course: 270.5, accuracy: 5.9
114996:2021-08-20 16:46:34  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:34, lat: 29.20164, lon: 79.50200, speed: 0.0, course: 338.1, accuracy: 6.5
115001:2021-08-20 16:46:51  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:35, lat: 29.20165, lon: 79.50200, speed: 0.0, course: 344.8, accuracy: 6.9
115022:2021-08-20 16:46:53  INFO: [78ab3248] id: 12333, time: 2021-08-20 16:46:36, lat: 29.20165, lon: 79.50200, speed: 0.0, course: 343.9, accuracy: 7.2
115025:2021-08-20 16:46:53  INFO: [8f0a6950] id: 12333, time: 2021-08-20 16:46:36, lat: 29.20165, lon: 79.50200, speed: 0.0, course: 343.9, accuracy: 7.2
115071:2021-08-20 16:49:03  INFO: [16c35bb5] id: 12333, time: 2021-08-20 16:46:37, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.4
115093:2021-08-20 16:49:04  INFO: [8e87639a] id: 12333, time: 2021-08-20 16:46:37, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.4
115099:2021-08-20 16:49:04  INFO: [5c178876] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115109:2021-08-20 16:49:06  INFO: [8e87639a] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115114:2021-08-20 16:49:26  INFO: [778cd7e0] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115139:2021-08-20 16:49:45  INFO: [b2b8e749] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115180:2021-08-20 16:49:47  INFO: [336511bc] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115190:2021-08-20 16:49:47  INFO: [1d819c60] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115220:2021-08-20 16:50:12  INFO: [93959777] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115233:2021-08-20 16:50:12  INFO: [cf470444] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115259:2021-08-20 16:50:12  INFO: [29e8afad] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115302:2021-08-20 16:50:12  INFO: [8f0a6950] id: 12333, time: 2021-08-20 16:46:37, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.4
115306:2021-08-20 16:50:13  INFO: [c8167564] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
115314:2021-08-20 16:50:13  INFO: [7c8adfb8] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3

other protocols:

2021-08-20 16:50:12  INFO: [40273c4f] id: 862462038826797, time: 2021-08-18 23:39:15, lat: 28.64779, lon: 77.19307, course: 233.0
2021-08-20 16:50:12  INFO: [40273c4f: m2c > 42.111.6.200] HEX: 5b302c312c302a3237365d
2021-08-20 16:50:12  INFO: [4a32fd68: m2c > 42.111.6.200] HEX: 5b302c312c302a3237355d
2021-08-20 16:50:12  INFO: [40273c4f: m2c > 42.111.6.200] HEX: 5b302c312c302a3237355d
2021-08-20 16:50:12  INFO: [40273c4f] id: 862462038826797, time: 2021-08-18 23:39:25, lat: 28.64779, lon: 77.19307, course: 233.0
2021-08-20 16:50:12  INFO: [40273c4f: m2c > 42.111.6.200] HEX: 5b302c312c302a3237365d
2021-08-20 16:50:12  INFO: [40273c4f: m2c > 42.111.6.200] HEX: 5b302c312c302a3237355d
2021-08-20 16:50:12  INFO: [4a32fd68] id: 862462038826797, time: 2021-08-20 16:47:34, lat: 28.64779, lon: 77.19309, course: 0.0
2021-08-20 16:50:12  INFO: [4a32fd68: m2c > 42.111.6.200] HEX: 5b302c312c302a3237365d
2021-08-20 16:50:12  INFO: [40273c4f] id: 862462038826797, time: 2021-08-20 16:49:38, lat: 28.64779, lon: 77.19309, course: 0.0
2021-08-20 16:50:12  INFO: [40273c4f: m2c > 42.111.6.200] HEX: 5b302c312c302a3237365d
2021-08-20 16:50:12  INFO: [8f0a6950: osmand < 103.148.181.194] HEX: 504f5354202f20485454502f312e310d0a436f6e74656e742d547970653a206170706c69636174696f6e2f6a736f6e3b20636861727365743d7574662d380d0a436f6e74656e742d4c656e6774683a203432310d0a486f73743a206170692e747261636b2e656e62616b652e636f6d3a353035350d0a436f6e6e656374696f6e3a204b6565702d416c6976650d0a4163636570742d456e636f64696e673a20677a69700d0a557365722d4167656e743a206f6b687474702f332e31322e310d0a0d0a7b226c6f636174696f6e223a7b2269735f6d6f76696e67223a747275652c2275756964223a2237356337376531342d363865342d343662342d626332302d653563366362613336656564222c2274696d657374616d70223a22323032312d30382d32305431313a31363a33372e3030305a222c226f646f6d65746572223a302c22636f6f726473223a7b226c61746974756465223a32392e3230313634352c226c6f6e676974756465223a37392e353031393935322c226163637572616379223a372e342c227370656564223a302c2273706565645f6163637572616379223a302e35352c2268656164696e67223a39302c2268656164696e675f6163637572616379223a2d312c22616c746974756465223a3336312e322c22616c7469747564655f6163637572616379223a342e397d2c226163746976697479223a7b2274797065223a227374696c6c222c22636f6e666964656e6365223a3130307d2c2262617474657279223a7b2269735f6368617267696e67223a747275652c226c6576656c223a302e31397d2c22657874726173223a7b7d7d2c226964223a223132333333227d
2021-08-20 16:50:12  INFO: [336511bc] disconnected
2021-08-20 16:50:12  INFO: [93959777] disconnected
2021-08-20 16:50:12  INFO: [92aead6b] disconnected
2021-08-20 16:50:12  INFO: [40273c4f] disconnected
2021-08-20 16:50:12  INFO: [8f0a6950: osmand > 103.148.181.194] HEX: 485454502f312e3120323030204f4b0d0a636f6e74656e742d6c656e6774683a20300d0a0d0a
2021-08-20 16:50:12  INFO: [8f0a6950] id: 12333, time: 2021-08-20 16:46:37, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.4
2021-08-20 16:50:12  INFO: [c8167564: osmand < 103.148.181.194] HEX: 504f5354202f20485454502f312e310d0a436f6e74656e742d547970653a206170706c69636174696f6e2f6a736f6e3b20636861727365743d7574662d380d0a436f6e74656e742d4c656e6774683a203432310d0a486f73743a206170692e747261636b2e656e62616b652e636f6d3a353035350d0a436f6e6e656374696f6e3a204b6565702d416c6976650d0a4163636570742d456e636f64696e673a20677a69700d0a557365722d4167656e743a206f6b687474702f332e31322e310d0a0d0a7b226c6f636174696f6e223a7b2269735f6d6f76696e67223a747275652c2275756964223a2231356463666337372d643562362d346439612d393834322d366363633537613063353939222c2274696d657374616d70223a22323032312d30382d32305431313a31363a34312e3030305a222c226f646f6d65746572223a302c22636f6f726473223a7b226c61746974756465223a32392e3230313634352c226c6f6e676974756465223a37392e353031393935332c226163637572616379223a372e332c227370656564223a302c2273706565645f6163637572616379223a302e31372c2268656164696e67223a39302c2268656164696e675f6163637572616379223a2d312c22616c746974756465223a3336312e312c22616c7469747564655f6163637572616379223a342e387d2c226163746976697479223a7b2274797065223a227374696c6c222c22636f6e666964656e6365223a3130307d2c2262617474657279223a7b2269735f6368617267696e67223a747275652c226c6576656c223a302e31397d2c22657874726173223a7b7d7d2c226964223a223132333333227d
2021-08-20 16:50:12  INFO: [c8167564: osmand > 103.148.181.194] HEX: 485454502f312e3120323030204f4b0d0a636f6e74656e742d6c656e6774683a20300d0a0d0a
2021-08-20 16:50:13  INFO: user: 1, action: logout
2021-08-20 16:50:13  INFO: [c8167564] id: 12333, time: 2021-08-20 16:46:41, lat: 29.20165, lon: 79.50200, course: 90.0, accuracy: 7.3
2021-08-20 16:50:13  INFO: [cb3408d5: m2c < 106.79.51.245] HEX: 244844522c32303235412c342e302e31382c4e522c30312c4c2c3836313335393033373634313135342c38393931303438333039313830303236383139342c4f2c312c32303038323032312c3131313935332c32382e3634373734372c4e2c37372e3139333130302c452c3030302e30302c3132372e35312c31382c3233352e372c566f6461666f6e652c33312c312c302c302c312c392e342c342e302c302e302c3033302e322c58312c58322c58332c39303235342c323635412a0d0a244844522c32303235412c342e302e31382c4e522c30312c4c2c3836313335393033373634313135342c38393931303438333039313830303236383139342c4f2c312c32303038323032312c3131323030332c32382e3634373734392c4e2c37372e3139333130302c452c3030302e30302c3132372e35312c31382c3233352e332c566f6461666f6e652c33312c312c302c302c312c392e342c342e302c302e302c3033302e312c58312c58322c58332c39303235352c323634422a0d0a
2021-08-20 16:50:13  INFO: [cb3408d5] id: 861359037641154, time: 2021-08-20 16:49:53, lat: 28.64775, lon: 77.19310, course: 127.5
2021-08-20 16:50:13  INFO: [cb3408d5: m2c > 106.79.51.245] HEX: 5b302c312c302a3237365d
2021-08-20 16:50:13  INFO: [cb3408d5] id: 861359037641154, time: 2021-08-20 16:50:03, lat: 28.64775, lon: 77.19310, course: 127.5
2021-08-20 16:50:13  INFO: [cb3408d5: m2c > 106.79.51.245] HEX: 5b302c312c302a3237365d

Thanks Anton.

Anton Tananaev4 years ago

Have you done any troubleshooting other than checking logs?

takliyah4 years ago

Please suggest what other trouble shooting can be done, since this is a random issue.?

Anton Tananaev4 years ago

Check if the port is open. Check if the port is responding. Those are the obvious ones.

I would also get a jstack dump to see if any thread are blocked.

takliyah4 years ago

Port was open, and restarting traccar solved it.
Port was not responding and timeout error was coming.

I do not have JStack dump of then, but in future will get it if any such behaviour. Present is this, if it helps.

2021-08-22 07:45:34
Full thread dump OpenJDK 64-Bit Server VM (11.0.8+10-LTS mixed mode):

Threads class SMR info:
_java_thread_list=0x00007f2d28000e90, length=35, elements={
0x00007f2d6c167800, 0x00007f2d6c16c000, 0x00007f2d6c180800, 0x00007f2d6c183000,
0x00007f2d6c185000, 0x00007f2d6c187000, 0x00007f2d6c1db000, 0x00007f2d6c1e4800,
0x00007f2d6cad8800, 0x00007f2d6cd77800, 0x00007f2d6d4c3800, 0x00007f2d6d4c5000,
0x00007f2d6d4c6800, 0x00007f2d6d4c9800, 0x00007f2d6d4ce000, 0x00007f2d6d4cf000,
0x00007f2d6d4d1000, 0x00007f2d6d4d3000, 0x00007f2d6d4f4800, 0x00007f2d6d4fa000,
0x00007f2d6d567000, 0x00007f2d6d9e2000, 0x00007f2d6da25000, 0x00007f2d6c027800,
0x00007f2d1c014800, 0x00007f2d4004f000, 0x00007f2d28007000, 0x00007f2d401a9000,
0x00007f2d3802f000, 0x00007f2d4c010000, 0x00007f2d3c2f3000, 0x00007f2d3010d000,
0x00007f2d300b6800, 0x00007f2d3c30d800, 0x00007f2d28005000
}


"VM Thread" os_prio=0 cpu=4071.88ms elapsed=69158.41s tid=0x00007f2d6c15f800 nid=0x2421 runnable

"GC Thread#0" os_prio=0 cpu=7103.39ms elapsed=69158.57s tid=0x00007f2d6c03f000 nid=0x241c runnable

"GC Thread#1" os_prio=0 cpu=7115.55ms elapsed=69157.88s tid=0x00007f2d3c001000 nid=0x242b runnable

"G1 Main Marker" os_prio=0 cpu=58.02ms elapsed=69158.56s tid=0x00007f2d6c05a000 nid=0x241d runnable

"G1 Conc#0" os_prio=0 cpu=12634.46ms elapsed=69158.56s tid=0x00007f2d6c05c000 nid=0x241e runnable

"G1 Refine#0" os_prio=0 cpu=330.52ms elapsed=69158.56s tid=0x00007f2d6c097800 nid=0x241f runnable

"G1 Refine#1" os_prio=0 cpu=115.57ms elapsed=67958.65s tid=0x00007f2d400e3000 nid=0x2577 runnable

"G1 Young RemSet Sampling" os_prio=0 cpu=38959.37ms elapsed=69158.56s tid=0x00007f2d6c099000 nid=0x2420 runnable
"VM Periodic Task Thread" os_prio=0 cpu=54487.75ms elapsed=69158.22s tid=0x00007f2d6c1dd800 nid=0x2429 waiting on condition

JNI global refs: 22, weak refs: 45
Anton Tananaev4 years ago

Doesn't really help. We need to see state when it stopped working.

takliyah4 years ago

Thanks Anton, please point apart from jstack if i need to collect anything else, if it pops next time?