Server not logging connections

David N5 years ago

I am running Traccar 4.5. I have a TK20 device that doesn't seem to be getting parsed by the server.

In the logs I see

2019-09-07 20:01:58  INFO: [f50e5118: tk103 < 172.56.4.189] HEX: 283836363633303033303231323935322c445733422c3037303931392c412c333435302e32323430314e2c30383233372e3832393734572c302e3133382c3230303135372c3030302e302c3331372e30302c372c3029283836363633303033303231323935322c5a4332302c3037303931392c3230303135362c362c3430382c36353533352c32353529

That decodes to:

(866630030212952,DW3B,070919,A,3450.22401N,08237.82974W,0.138,200157,000.0,317.00,7,0)(866630030212952,ZC20,070919,200156,6,408,65535,255)

So clearly getting Hex to the box. -

I have added the identifier 866630030212952. But with or without an identifier, there doesn't seem to be anything additional in the logs. I get neither an INFO log with coordinates nor an unknown device warning.

The protocol looks to be Tk103, and it's on port 5002. I've even added the first line into the Tk103ProtocolDecoderTest.java - and then run mvn test, and the tests pass successfully, so it would appear to be capable of decoding it.

I've also tried changing logging level from info to all - but it doesn't appear to have added any probative data (log below)
I do successfully have iPhone and Android traccar clients reporting into this, but none of my Tk20 devices seem to be working. I am certain I am missing something easy server side, but not sure what it is.

2019-09-07 20:11:52  INFO: [f50e5118: tk103 < 172.56.5.181] HEX: 283836363633303033303231323935322c445733422c3037303931392c412c333435302e32333033364e2c30383233372e3835303732572c302e3032342c3230313135312c3030302e302c3334392e37302c382c3029283836363633303033303231323935322c5a4332302c3037303931392c3230313135302c362c3430382c36353533352c32353529
2019-09-07 20:11:58 DEBUG: HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2019-09-07 20:12:28 DEBUG: HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2019-09-07 20:12:43 DEBUG: shrinking org.eclipse.jetty.util.thread.QueuedThreadPool$Runner@6657e00e
2019-09-07 20:12:58 DEBUG: HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2019-09-07 20:13:28 DEBUG: HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2019-09-07 20:13:58 DEBUG: HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2019-09-07 20:13:58 TRACE:   simple execute, handler={0}, maxRows={1}, fetchSize={2}, flags={3}
2019-09-07 20:13:58 TRACE:  FE=> Parse(stmt=S_1,query="",oids={})
2019-09-07 20:13:58 TRACE:  FE=> Bind(stmt=S_1,portal=null)
2019-09-07 20:13:58 TRACE:  FE=> Describe(portal={0})
2019-09-07 20:13:58 TRACE:  FE=> Execute(portal={0},limit={1})
2019-09-07 20:13:58 TRACE:  FE=> Sync
2019-09-07 20:13:58 TRACE:  <=BE ParseComplete [{0}]
2019-09-07 20:13:58 TRACE:  <=BE BindComplete [{0}]
2019-09-07 20:13:58 TRACE:  <=BE NoData
2019-09-07 20:13:58 TRACE:  <=BE EmptyQuery
2019-09-07 20:13:58 TRACE:  <=BE ReadyForQuery({0})
2019-09-07 20:13:58 TRACE:   simple execute, handler={0}, maxRows={1}, fetchSize={2}, flags={3}
2019-09-07 20:13:58 TRACE:  FE=> Parse(stmt=null,query="INSERT INTO tc_events (maintenanceId, serverTime, positionId, attributes, geofenceId, deviceId, type) VALUES ($1, $2, $3, $4, $5, $6, $7)
RETURNING *",oids={23,0,23,1043,23,20,1043})
2019-09-07 20:13:58 TRACE:  FE=> Bind(stmt=null,portal=null,$1=<NULL>,type=INT4,$2=<'2019-09-07 20:13:58.839+00'>,type=UNSPECIFIED,$3=<NULL>,type=INT4,$4=<'{}'>,type=VARCHAR,$5=<NULL>,type=INT4,$6=<2>,type=INT8,$7=<'deviceUnknown'>,type=VARCHAR)
2019-09-07 20:13:58 TRACE:  FE=> Describe(portal={0})
2019-09-07 20:13:58 TRACE:  FE=> Execute(portal={0},limit={1})
2019-09-07 20:13:58 TRACE:  FE=> Sync
2019-09-07 20:13:58 TRACE:  <=BE ParseComplete [{0}]
2019-09-07 20:13:58 TRACE:  <=BE BindComplete [{0}]
2019-09-07 20:13:58 TRACE:  <=BE RowDescription({0})
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:         {0}
2019-09-07 20:13:58 TRACE:  <=BE DataRow(len={0})
2019-09-07 20:13:58 TRACE:  <=BE CommandStatus({0})
2019-09-07 20:13:58 TRACE:  <=BE ReadyForQuery({0})
2019-09-07 20:13:58 TRACE:   getLong columnIndex: {0}
2019-09-07 20:13:58 TRACE:   simple execute, handler={0}, maxRows={1}, fetchSize={2}, flags={3}
2019-09-07 20:13:58 TRACE:  FE=> Parse(stmt=null,query="UPDATE tc_devices SET lastUpdate = $1 WHERE id = $2",oids={0,20})
2019-09-07 20:13:58 TRACE:  FE=> Bind(stmt=null,portal=null,$1=<'2019-09-07 20:03:58.745+00'>,type=UNSPECIFIED,$2=<2>,type=INT8)
2019-09-07 20:13:58 TRACE:  FE=> Describe(portal={0})
2019-09-07 20:13:58 TRACE:  FE=> Execute(portal={0},limit={1})
2019-09-07 20:13:58 TRACE:  FE=> Sync
2019-09-07 20:13:58 TRACE:  <=BE ParseComplete [{0}]
2019-09-07 20:13:58 TRACE:  <=BE BindComplete [{0}]
2019-09-07 20:13:58 TRACE:  <=BE NoData
2019-09-07 20:13:58 TRACE:  <=BE CommandStatus({0})
2019-09-07 20:13:58 TRACE:  <=BE ReadyForQuery({0})
2019-09-07 20:13:58 DEBUG: sendString(HeapByteBuffer@19b0133d[p=0,l=258,c=258,r=258]={<<<{"devices":[{"id"...abled":false}]}>>>},null)
2019-09-07 20:13:58 DEBUG: Queuing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Processing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Queuing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Processing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Compressing TEXT[len=258,fin=true,rsv=...,masked=false]: 258 bytes in 258 bytes chunk
2019-09-07 20:13:58 DEBUG: Supplied 258 input bytes: Deflater[finished=false,read=1014,written=412,in=1014,out=412]
2019-09-07 20:13:58 DEBUG: Wrote 150 bytes to output buffer
2019-09-07 20:13:58 DEBUG: compressed bytes[] = HeapByteBuffer@5cb29e6f[p=0,l=150,c=150,r=150]={<<<t\x94\xC1\n\x830\x0c\x86\xDf\xA5o\xA0\xE2\xC0G\xF0\xE2...\x9b\x043c1tbi\t\xAc\x00\x00\x00\xFf\xFf>>>}
2019-09-07 20:13:58 DEBUG: payload (TAIL_DROP_ALWAYS) = HeapByteBuffer@5cb29e6f[p=0,l=146,c=150,r=146]={<<<t\x94\xC1\n\x830\x0c\x86\xDf\xA5o\xA0\xE2\xC0G\xF0\xE2...\xAcY\xE4\xE9\x9b\x043c1tbi\t\xAc\x00>>>\x00\x00\xFf\xFf}
2019-09-07 20:13:58 DEBUG: Compressed TEXT[len=0,fin=true,rsv=...,masked=false]: input:258 -> payload:146
2019-09-07 20:13:58 DEBUG: nextOutgoingFrame(TEXT[len=146,fin=true,rsv=1..,masked=false])
2019-09-07 20:13:58 DEBUG: outgoingFrame(TEXT[len=146,fin=true,rsv=1..,masked=false], org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@202d1d7[PROCESSING])
2019-09-07 20:13:58 DEBUG: Enqueued FrameEntry[TEXT[len=146,fin=true,rsv=1..,masked=false],org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@202d1d7[PROCESSING],AUTO,null] to org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[IDLE][queueSize=1,aggregateSize=-1,terminated=null]
2019-09-07 20:13:58 DEBUG: Flushing org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=1,aggregateSize=-1,terminated=null]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=-1,terminated=null] processing 1 entries: [FrameEntry[TEXT[len=146,fin=true,rsv=1..,masked=false],org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@202d1d7[PROCESSING],AUTO,null]]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] acquired aggregate buffer java.nio.DirectByteBuffer[pos=0 lim=0 cap=32768]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] aggregated 1 frames: [FrameEntry[TEXT[len=0,fin=true,rsv=1..,masked=false],org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@202d1d7[PROCESSING],AUTO,null]]
2019-09-07 20:13:58 DEBUG: Flushing org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=0,terminated=null]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] processing 0 entries: []
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] auto flushing
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] flushing aggregate java.nio.DirectByteBuffer[pos=0 lim=150 cap=32768]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] flushing 0 frames: []
2019-09-07 20:13:58 DEBUG: write: WriteFlusher@5427bc32{IDLE}->null [DirectByteBuffer@4a05c9ef[p=0,l=150,c=32768,r=150]={<<<\xC1~\x00\x92t\x94\xC1\n\x830\x0c\x86\xDf\xA5o\xA0\xE2...\xAcY\xE4\xE9\x9b\x043c1tbi\t\xAc\x00>>>%\x0e\x91< \xE6\xAd\x9dF`\x90]\xDa\xBb\xB4\xF1[...eldLabel:String}]
2019-09-07 20:13:58 DEBUG: update WriteFlusher@5427bc32{WRITING}->null:IDLE-->WRITING
2019-09-07 20:13:58 DEBUG: flushed 150 SocketChannelEndPoint@1a7be0e{/127.0.0.1:49292<->/127.0.0.1:8082,OPEN,fill=FI,flush=W,to=375261/600000}{io=1/1,kio=1,kro=1}->WebSocketServerConnection@7081ac4b[s=ConnectionState@cce98c1[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=150,terminated=null],g=Generator[SERVER,validating,+rsv1],p=Parser@32147007[ExtensionStack,s=START,c=0,len=0,f=null]]
2019-09-07 20:13:58 DEBUG: Flushed=true written=150 remaining=0 WriteFlusher@5427bc32{WRITING}->null
2019-09-07 20:13:58 DEBUG: update WriteFlusher@5427bc32{IDLE}->null:WRITING-->IDLE
2019-09-07 20:13:58 DEBUG: Flushing org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=150,terminated=null]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=150,terminated=null] processing 0 entries: []
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=150,terminated=null] auto flushing
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@563cd804[PROCESSING][queueSize=0,aggregateSize=150,terminated=null] flushing 0 frames: []
2019-09-07 20:13:58 DEBUG: Processing null
2019-09-07 20:13:58 DEBUG: Entering IDLE
2019-09-07 20:13:58 DEBUG: sendString(HeapByteBuffer@ce80fa4[p=0,l=258,c=258,r=258]={<<<{"devices":[{"id"...abled":false}]}>>>},null)
2019-09-07 20:13:58 DEBUG: Queuing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Processing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Queuing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Processing TEXT[len=258,fin=true,rsv=...,masked=false]
2019-09-07 20:13:58 DEBUG: Compressing TEXT[len=258,fin=true,rsv=...,masked=false]: 258 bytes in 258 bytes chunk
2019-09-07 20:13:58 DEBUG: Supplied 258 input bytes: Deflater[finished=false,read=2550,written=695,in=2550,out=695]
2019-09-07 20:13:58 DEBUG: Wrote 23 bytes to output buffer
2019-09-07 20:13:58 DEBUG: compressed bytes[] = HeapByteBuffer@6da40759[p=0,l=23,c=23,r=23]={<<<\xA2C\xFa/\xCd\xCb\xCe\xCb/\xCf\xA30\x03\x18\xD2*\x03\x00\x00\x00\x00\xFf\xFf>>>}
2019-09-07 20:13:58 DEBUG: payload (TAIL_DROP_FIN_ONLY) = HeapByteBuffer@6da40759[p=0,l=19,c=23,r=19]={<<<\xA2C\xFa/\xCd\xCb\xCe\xCb/\xCf\xA30\x03\x18\xD2*\x03\x00\x00>>>\x00\x00\xFf\xFf}
2019-09-07 20:13:58 DEBUG: Compressed TEXT[len=0,fin=true,rsv=...,masked=false]: input:258 -> payload:19
2019-09-07 20:13:58 DEBUG: nextOutgoingFrame(TEXT[len=19,fin=true,rsv=1..,masked=false])
2019-09-07 20:13:58 DEBUG: outgoingFrame(TEXT[len=19,fin=true,rsv=1..,masked=false], org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@462dd0f4[PROCESSING])
2019-09-07 20:13:58 DEBUG: Enqueued FrameEntry[TEXT[len=19,fin=true,rsv=1..,masked=false],org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@462dd0f4[PROCESSING],AUTO,null] to org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[IDLE][queueSize=1,aggregateSize=-1,terminated=null]
2019-09-07 20:13:58 DEBUG: Flushing org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=1,aggregateSize=-1,terminated=null]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=-1,terminated=null] processing 1 entries: [FrameEntry[TEXT[len=19,fin=true,rsv=1..,masked=false],org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@462dd0f4[PROCESSING],AUTO,null]]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] acquired aggregate buffer java.nio.DirectByteBuffer[pos=0 lim=0 cap=32768]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] aggregated 1 frames: [FrameEntry[TEXT[len=0,fin=true,rsv=1..,masked=false],org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension$Flusher@462dd0f4[PROCESSING],AUTO,null]]
2019-09-07 20:13:58 DEBUG: Flushing org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=0,terminated=null]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] processing 0 entries: []
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] auto flushing
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] flushing aggregate java.nio.DirectByteBuffer[pos=0 lim=21 cap=32768]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=0,terminated=null] flushing 0 frames: []
2019-09-07 20:13:58 DEBUG: write: WriteFlusher@27da1311{IDLE}->null [DirectByteBuffer@4a05c9ef[p=0,l=21,c=32768,r=21]={<<<\xC1\x13\xA2C\xFa/\xCd\xCb\xCe\xCb/\xCf\xA30\x03\x18\xD2*\x03\x00\x00>>>i;\xEe\xD0\xB9Ze#q\x9a\xB0\r_\xDe\xFcb\x11...eldLabel:String}]
2019-09-07 20:13:58 DEBUG: update WriteFlusher@27da1311{WRITING}->null:IDLE-->WRITING
2019-09-07 20:13:58 DEBUG: flushed 21 SocketChannelEndPoint@34e107a4{/127.0.0.1:49272<->/127.0.0.1:8082,OPEN,fill=FI,flush=W,to=599680/600000}{io=1/1,kio=1,kro=1}->WebSocketServerConnection@60a18989[s=ConnectionState@7a13021d[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=21,terminated=null],g=Generator[SERVER,validating,+rsv1],p=Parser@7a04fd6[ExtensionStack,s=START,c=0,len=0,f=null]]
2019-09-07 20:13:58 DEBUG: Flushed=true written=21 remaining=0 WriteFlusher@27da1311{WRITING}->null
2019-09-07 20:13:58 DEBUG: update WriteFlusher@27da1311{IDLE}->null:WRITING-->IDLE
2019-09-07 20:13:58 DEBUG: Flushing org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=21,terminated=null]
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=21,terminated=null] processing 0 entries: []
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=21,terminated=null] auto flushing
2019-09-07 20:13:58 DEBUG: org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@15588169[PROCESSING][queueSize=0,aggregateSize=21,terminated=null] flushing 0 frames: []
2019-09-07 20:13:58 DEBUG: Processing null
2019-09-07 20:13:58 DEBUG: Entering IDLE
RICARDO5 years ago

Hello good morning, I have the following problem, I configure the skypatrol tracker TT9200 and the return in the log file
is coming without the coordinates just with imei.

2019-09-08 07:33:01  INFO: [eead03a8: enfora < 177.115.100.154] HEX: 00050200000000000120202020202038363231393330323139373033353520