Identifying cause of errors after edits to tc_positions in database

Smashers0902 months ago

Background

Running traccar v6.5 on ubuntu debian with external postgresql database.

I've been attempting to repair a specific case of incorrect fixtime records in tc_position. The attempt was very simple; following an analysis of positions data, I identified a set of position.id's which were out of sync by 90 minutes on 17th October 2024.

UPDATE tc_positions
SET fixtime = fixtime - INTERVAL '90 minutes'
WHERE id IN (14881, 14889, 14897, 14905, 14913, 14919, 14948, 14986, 15034);

A simple change, regretfully applied while the traccar service was running, although I can't confirm whether this is a factor.

Issue

Following this change, any GET /positions API call (via traccar-web /replay) overlapping the range 17 Oct - 22 Oct results in the same error, e.g.:

GET /api/positions?deviceId=10&from=2024-09-30T23%3A00%3A00.000Z&to=2024-10-31T23%3A59%3A59.999Z

-> net::ERR_INCOMPLETE_CHUNKED_ENCODING 200 (OK)
and Failed to fetch toast in web app.

Even after reverting the operation:

UPDATE tc_positions
SET fixtime = fixtime + INTERVAL '90 minutes'
WHERE id IN (14881, 14889, 14897, 14905, 14913, 14919, 14948, 14986, 15034);

The issue persists. Curiously, this issue also affects devices other than the device whose records were edited.

Steps I have tried:

  • Inspected traccar service logs, including when API call is made -> no visible logs at DEBUG or higher
  • Inspected updated fixtime values for data format inconsistencies (None apparent. Column of type 'timestamp without time zone')
  • Reverting the UPDATE operation as shown above
  • Rebuilding the table index position_deviceid_fixtime
  • Validating indexes with amcheck bt_index_check()
  • Set valid = false for the records I had changed, in order to exclude.
  • Restart traccar server between each attempted step, and verify.

I have inspected the traccar source code, exploring Position model, PositionResource /positions path definition, storage.getObjects() execution logic; I cannot identify what might be causing the returned error after much effort.

Other ideas

  • Cache causing issue to persist after reverse DB operation
  • Database trigger or traccar service logic resulted in changes outside tc_position after the intial UPDATE operation, which persist
  • UPDATE operation lost timezone-related information (not evident)
  • Wild goose chase - issue unrelated to UPDATE operation (not likely - low-activity server in development; new issue on day of UPDATE, affected dates align)

My Questions

  • A question to the devs please: in your view, what is most likely to have broken or caused this issue following my simple UPDATE operation?
  • And to other users: have you experienced anything similar?
Anton Tananaev2 months ago

Have you provided Accept header with your request?

Smashers0902 months ago

Thank you for your attention, Anton. Described above, if not clearly, this issue is not with direct API calls but with the /replay webpage's call of that API; so, headers are handled by traccar.

I prepared an update with logs and more clarity, which I will share next.

Updates

It's become a lot more curious.

Making the same request via Postman with Bearer Token authentication for the same user as in the web UI returns data, 100% of the time.

It seems likely an error occuring in the frontend - not the API but the handling of the API's response. I'm shifting my attention to the web codebase and how the response is handled.

Sample response for future reference

This response includes:

  • records I did not edit, marked as valid=true
  • a record I edited and reverted, marked as valid=false

NB: I can't see anything wrong with the edited record. The fact these are duplicate positions is not the issue, but the fixtime > device/servertime is the root issue my UPDATE statement is aimed to resolve. 

[
    { # a record I didn't change
        "id": 14879,
        "attributes": {
            "sat": 6,
            "distance": 0.0,
            "totalDistance": 7058249.733549142,
            "motion": false
        },
        "deviceId": 10,
        "protocol": "topin",
        "serverTime": "2024-10-17T11:47:17.274+00:00",
        "deviceTime": "2024-10-17T12:41:03.000+00:00",
        "fixTime": "2024-10-17T12:41:03.000+00:00",
        "outdated": false,
        "valid": true,
        "latitude": 55.647304999999996,
        "longitude": -3.887045,
        "altitude": 196.0,
        "speed": 0.0,
        "course": 323.0,
        "address": null,
        "accuracy": 0.0,
        "network": null,
        "geofenceIds": null
    },
    {  # the record I edited with UPDATE statement
        "id": 14881,
        "attributes": {
            "batteryLevel": 97,
            "versionFw": 96,
            "rssi": 3,
            "distance": 0.0,
            "totalDistance": 7058249.733549142,
            "motion": false
        },
        "deviceId": 10,
        "protocol": "topin",
        "serverTime": "2024-10-17T11:49:42.383+00:00",
        "deviceTime": "2024-10-17T11:49:42.383+00:00",
        "fixTime": "2024-10-17T12:41:03.000+00:00",
        "outdated": false,
        "valid": false, # manually set
        "latitude": 55.647304999999996,
        "longitude": -3.887045,
        "altitude": 196.0,
        "speed": 0.0,
        "course": 323.0,
        "address": null,
        "accuracy": 0.0,
        "network": null,
        "geofenceIds": null 
    },

Inconsistency

After many confused attempts in frontend /replay, I notice sometimes an exact same filter will succeed, or fail. I think a cache is also at play, as the same request in close succession will see the same success or error outcome each time for a short time. But come back later and it may have switched. This inconsistency is confusing.

api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z - Reponse as expected
api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z - Failed to Fetch, net::ERR_INCOMPLETE_CHUNKED_ENCODING

Traccar server logs

I have found logs from one of the failed requests: 

2024-11-01 18:50:12 DEBUG: REQUEST for /api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z on HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=0}
2024-11-01 18:50:12 DEBUG: HttpConnection@4ef4e59f::SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=START}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=0}] parsed true HttpParser{s=CONTENT,0 of -1}
2024-11-01 18:50:12 DEBUG: releaseRequestBuffer HttpConnection@4ef4e59f::SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=START}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=0}]
2024-11-01 18:50:12 DEBUG: handle http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=0}
2024-11-01 18:50:12 DEBUG: action DISPATCH HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=0}
2024-11-01 18:50:12 DEBUG: REQUEST GET /api/positions ?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z on HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=0}
2024-11-01 18:50:12 DEBUG: Request Request(GET http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z)@624d90b6 entering session=Session@2cc406df{id=node0m97bkf18s3z0czi785fnkii41,x=node0m97bkf18s3z0czi785fnkii41.node0,req=1,res=true}
2024-11-01 18:50:12 DEBUG: COMMIT for /api/positions on HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=15}
2024-11-01 18:50:12 DEBUG: Response Request(GET http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z)@624d90b6 committing for session Session@2cc406df{id=node0m97bkf18s3z0czi785fnkii41,x=node0m97bkf18s3z0czi785fnkii41.node0,req=1,res=true}
2024-11-01 18:50:12 DEBUG: flushed 33090 SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OPEN,fill=-,flush=W,to=18/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=COMMITTED}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=16}]
2024-11-01 18:50:12 DEBUG: flushed 32768 SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OPEN,fill=-,flush=W,to=3/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=COMMITTED}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=20}]
2024-11-01 18:50:12 DEBUG: flushed 32768 SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OPEN,fill=-,flush=W,to=2/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=COMMITTED}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=23}]
2024-11-01 18:50:12 DEBUG: flushed 21378 SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OPEN,fill=-,flush=W,to=1/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=COMMITTED}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=24}]
2024-11-01 18:50:12 DEBUG: handled=true async=false committed=true on HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=BLOCKING os=COMMITTED is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=25}
2024-11-01 18:50:12 DEBUG: action COMPLETE HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=COMPLETING os=COMMITTED is=IDLE awp=false se=false i=false al=0},r=1,c=false/false,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=25}
2024-11-01 18:50:12 DEBUG: shutdownOutput SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=END}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=HANDLING rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=HANDLING,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=25}]
2024-11-01 18:50:12 DEBUG: action TERMINATED HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=25}
2024-11-01 18:50:12 DEBUG: Request Request[GET http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z]@624d90b6 leaving session Session@2cc406df{id=node0m97bkf18s3z0czi785fnkii41,x=node0m97bkf18s3z0czi785fnkii41.node0,req=1,res=true}
2024-11-01 18:50:12 DEBUG: failing all content with org.eclipse.jetty.util.StaticException: Unconsumed content HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=26}
2024-11-01 18:50:12 DEBUG: HttpConnection@4ef4e59f::SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OSHUT,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@674c4ea9{s=END}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=26}] parse null
2024-11-01 18:50:12 DEBUG: onContentComplete HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=26}
2024-11-01 18:50:12 DEBUG: onRequestComplete HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=26}
2024-11-01 18:50:12 DEBUG: HttpConnection@4ef4e59f::SocketChannelEndPoint@339aa3a9[{l=/127.0.0.1:8082,r=/127.0.0.1:41428,OSHUT,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@4ef4e59f[p=HttpParser{s=END,0 of -1},g=HttpGenerator@674c4ea9{s=END}]=>HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=26}] parsed false HttpParser{s=END,0 of -1}
2024-11-01 18:50:12 DEBUG: failed all content of http channel EOF=true AsyncContentProducer@310b31f6[r=ErrorContent [org.eclipse.jetty.util.StaticException: Unconsumed content],t=ErrorContent [org.eclipse.jetty.util.StaticException: Unconsumed content],i=null,error=false,c=HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=26}]
2024-11-01 18:50:12 DEBUG: isError = false AsyncContentProducer@310b31f6[r=ErrorContent [org.eclipse.jetty.util.StaticException: Unconsumed content],t=ErrorContent [org.eclipse.jetty.util.StaticException: Unconsumed content],i=null,error=false,c=HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=COMPLETED os=COMPLETED is=IDLE awp=false se=false i=false al=0},r=1,c=true/true,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=27}]
2024-11-01 18:50:12 DEBUG: recycling AsyncContentProducer@310b31f6[r=ErrorContent [org.eclipse.jetty.util.StaticException: Unconsumed content],t=ErrorContent [org.eclipse.jetty.util.StaticException: Unconsumed content],i=null,error=false,c=HttpChannelOverHttp@b9e5f5{s=HttpChannelState@2efc9de6{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=http://my.domain.com/api/positions?deviceId=20&from=2024-10-16T23%3A00%3A00.000Z&to=2024-10-17T22%3A59%3A00.000Z,age=27}]

Not my strongest area, but the error org.eclipse.jetty.util.StaticException: Unconsumed content might mean there is a mismatch between content length and the data sent, serialization issues, or something else... now to find out why and what to do about it.

Any thoughts welcome.

Anton Tananaev2 months ago

And you're connecting directly to Traccar? No reverse proxy?

Smashers0902 months ago

I'm using nginx. Traccar is running on localhost:8082, Nginx handles SSL termination & forwards incoming HTTPS requests. My nginx config includes server blocks listen on port 443 for HTTPS connections, with proxy_pass directives pointing to the Traccar service.

That's a good thought. You prompted me to check the config, and I've made a few small changes;

  • added http v1.1 in location /
  • increased buffer size from default
  • increased read/send timeouts

Things seem ok at the moment - I'll have to test further and continue with fixing the bad fixtime records.

On that topic - I should be fine to alter fixtime directly using UPDATE on the tc_positions? Any extra care needed other than common sense?

Anton Tananaev2 months ago

Updating the positions table should be fine. Just make sure you restart service after.

Smashers0902 months ago

Thank you, appreciate it.