search

schollz / find3

High-precision indoor positioning framework, version 3.
https://www.internalpositioning.com/doc
MIT License
4.66k stars 364 forks source link

Sqlite3 reporting database is locked? #54

Closed victorhooi closed 6 years ago

victorhooi commented 6 years ago

I'm seeing lots of lines stating database is locked in my find3 logfile:

2018-04-11 05:01:13 [WARN] [PID-12] analysis.go AnalyzeSensorData:117 [gcc] nb1 classify: problem preparing SQL: database is locked
2018-04-11 05:01:13 [WARN] [PID-12] analysis.go AnalyzeSensorData:117 [gcc] nb1 classify: problem preparing SQL: database is locked
2018-04-11 05:01:14 [WARN] [PID-12] analysis.go AnalyzeSensorData:117 [gcc] nb1 classify: problem preparing SQL: database is locked
2018-04-11 05:01:15 [WARN] [PID-12] analysis.go AnalyzeSensorData:117 [gcc] nb1 classify: problem preparing SQL: database is locked
2018-04-11 05:01:15 [WARN] [PID-12] server.go parseRollingData:883 [gcc] problem saving: Columns: database is locked
2018-04-11 05:01:15 [DEBUG] [PID-12] server.go parseRollingData:885 [gcc] saved reverse sensor data for wifi-48:bf:6b:18:66:76
2018-04-11 05:01:15 [DEBUG] [PID-12] server.go parseRollingData:874 [gcc] reverse sensor data: {Timestamp:1523422719868 Family:gcc Device:wifi-32:8f:a9:d2:30:ea Location: Sensors:map[wifi:map[entrance-wifi:-77]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-11 05:01:15 [WARN] [PID-12] server.go parseRollingData:883 [gcc] problem saving: Columns: database is locked
2018-04-11 05:01:15 [DEBUG] [PID-12] server.go parseRollingData:885 [gcc] saved reverse sensor data for wifi-2a:09:44:9c:fa:16
2018-04-11 05:01:15 [DEBUG] [PID-12] server.go parseRollingData:874 [gcc] reverse sensor data: {Timestamp:1523422721323 Family:gcc Device:wifi-ba:e3:39:b3:0c:0e Location: Sensors:map[wifi:map[kidsroom-wifi:-77]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-11 05:01:15 [WARN] [PID-12] analysis.go AnalyzeSensorData:117 [gcc] nb1 classify: problem preparing SQL: database is locked
2018-04-11 05:01:15 [WARN] [PID-12] server.go parseRollingData:883 [gcc] problem saving: AddSensor, execute: database is locked
2018-04-11 05:01:15 [DEBUG] [PID-12] server.go parseRollingData:885 [gcc] saved reverse sensor data for wifi-30:87:d9:b1:1d:e8
2018-04-11 05:01:15 [DEBUG] [PID-12] server.go parseRollingData:874 [gcc] reverse sensor data: {Timestamp:1523422720304 Family:gcc Device:wifi-f0:d7:aa:c5:9c:3b Location: Sensors:map[wifi:map[mainhallleft-wifi:-75 mainhallright-wifi:-79]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-11 05:01:16 [WARN] [PID-12] server.go parseRollingData:883 [gcc] problem saving: AddSensor, execute: database is locked
2018-04-11 05:01:16 [DEBUG] [PID-12] server.go parseRollingData:885 [gcc] saved reverse sensor data for wifi-5e:7e:32:e1:01:93
2018-04-11 05:01:16 [DEBUG] [PID-12] server.go parseRollingData:874 [gcc] reverse sensor data: {Timestamp:1523422717748 Family:gcc Device:wifi-d6:4c:24:15:bb:71 Location: Sensors:map[wifi:map[entrance-wifi:-73]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-11 05:01:16 [WARN] [PID-12] server.go parseRollingData:883 [gcc] problem saving: AddSensor, execute: database is locked
2018-04-11 05:01:16 [DEBUG] [PID-12] server.go parseRollingData:885 [gcc] saved reverse sensor data for wifi-16:ec:aa:9b:db:2a
2018-04-11 05:01:16 [DEBUG] [PID-12] server.go parseRollingData:874 [gcc] reverse sensor data: {Timestamp:1523422719847 Family:gcc Device:wifi-ba:12:68:ed:6b:54 Location: Sensors:map[wifi:map[entrance-wifi:-65 mainhallright-wifi:-69 kidsroom-wifi:-75]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-11 05:01:18 [WARN] [PID-12] analysis.go AnalyzeSensorData:117 [gcc] nb1 classify: problem preparing SQL: database is locked
2018-04-11 05:01:19 [WARN] [PID-12] server.go handlerReverse:812 Set: database is locked
2018-04-11 05:01:19 [INFO] [PID-12] server.go func1:971 172.27.207.39:56610 POST /passive 15.349143496s

And then in my passive scanners:

2018-04-11 05:03:24 [DEBUG] server-main.go postData:47 posting data
2018-04-11 05:03:24 [ERROR] main.go reverseCapture:122 Post http://172.27.181.166:8005/passive: dial tcp 172.27.181.166:8005: connect: connection refused
2018-04-11 05:03:24 [INFO] main.go main:79 reverse scanning with wlan1
2018-04-11 05:03:24 [DEBUG] reverse.go ReverseScan:23 saving tshark data to /tmp/tshark-JIDeBSEgjd
2018-04-11 05:03:24 [DEBUG] reverse.go ReverseScan:23 tshark -I -i wlan1 -a duration:40 -w /tmp/tshark-JIDeBSEgjd
2018-04-11 05:03:24 [DEBUG] utils.go RunCommand:14 tshark -I -i wlan1 -a duration:40 -w /tmp/tshark-JIDeBSEgjd

Is it possible I've hit some limit on Sqlite3?

I have 5 passive scanners (running on Raspberry Pis).

schollz commented 6 years ago

@victorhooi I've never had that issue... I'm using a separate locking file for SQLite access so it seems that that ran into some race condition (possibly deleting a file that was created by another process so it thought it was okay to write). I think I need to do some load testing to see if I can reproduce

victorhooi commented 6 years ago

Will it help if I share with you my sqlite db files? Or the logfiles?

Or I can give you private access to the system?

schollz commented 6 years ago

@victorhooi Maybe the db. But first - did you ever get it to unlock?

victorhooi commented 6 years ago

I checked just now, and I'm not seeing the database is locked lines. However, I did shutdown 2 of the 5 Raspberry PI passive trackers.

My SQLite3 database file is around 800 MB...file size limit here is 25MB.

Any other thoughts on best way to get it across to you?

UPDATE - bzip2 managed to get it down to 78 MB.

victorhooi commented 6 years ago

@schollz Uploaded to Slack for you.

schollz commented 6 years ago

This should be fixed with https://github.com/schollz/find3/commit/c787ee806f46016ee17b007d5cc690914496df6f

victorhooi commented 6 years ago

I'm still seeing this a lot - particularly when I try to access the dashboard:

2018-04-28 22:32:34 [DEBUG] [PID-12] db.go AddSensor:350 [gcc] inserted sensor data, 49.05879ms
2018-04-28 22:32:35 [DEBUG] [PID-12] server.go 1:140 [gcc] getting device counts
2018-04-28 22:32:40 [WARN] [PID-12] server.go parseRollingData:890 [gcc] problem saving: problem getting device ID: AddName: database is locked
2018-04-28 22:32:40 [DEBUG] [PID-12] server.go parseRollingData:892 [gcc] saved reverse sensor data for wifi-c2:23:f8:40:10:8b
2018-04-28 22:32:40 [DEBUG] [PID-12] server.go parseRollingData:881 [gcc] reverse sensor data: {Timestamp:1524954750413 Family:gcc Device:wifi-00:26:08:fa:d2:ef Location: Sensors:map[wifi:map[entrance-wifi:-69]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-28 22:32:50 [WARN] [PID-12] server.go parseRollingData:890 [gcc] problem saving: AddSensor: database is locked
2018-04-28 22:32:50 [DEBUG] [PID-12] server.go parseRollingData:892 [gcc] saved reverse sensor data for wifi-00:26:08:fa:d2:ef
2018-04-28 22:32:50 [DEBUG] [PID-12] server.go parseRollingData:881 [gcc] reverse sensor data: {Timestamp:1524954750465 Family:gcc Device:wifi-e2:b9:e5:ac:5e:5e Location: Sensors:map[wifi:map[mainhallleft-wifi:-73 kidsroom-wifi:-75 entrance-wifi:-75 mainhallright-wifi:-77]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-28 22:32:50 [WARN] [PID-12] analysis.go AnalyzeSensorData:117 [gcc] nb1 classify: problem preparing SQL: database is locked
2018-04-28 22:32:55 [WARN] [PID-12] server.go parseRollingData:890 [gcc] problem saving: AddSensor: database is locked
2018-04-28 22:32:55 [DEBUG] [PID-12] server.go parseRollingData:892 [gcc] saved reverse sensor data for wifi-e2:b9:e5:ac:5e:5e
2018-04-28 22:32:55 [DEBUG] [PID-12] server.go parseRollingData:881 [gcc] reverse sensor data: {Timestamp:1524954750702 Family:gcc Device:wifi-08:3e:5d:13:48:46 Location: Sensors:map[wifi:map[entrance-wifi:-75 cafetv-wifi:-73]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-28 22:32:57 [WARN] [PID-12] server.go handlerReverse:819 Set: database is locked
2018-04-28 22:32:57 [INFO] [PID-12] server.go func1:978 172.27.177.141:60532 POST /passive 10.049664648s
2018-04-28 22:33:00 [WARN] [PID-12] server.go handlerReverse:819 Set: database is locked
2018-04-28 22:33:00 [INFO] [PID-12] server.go func1:978 172.27.198.243:55060 POST /passive 16.998434206s
2018-04-28 22:33:00 [WARN] [PID-12] server.go parseRollingData:890 [gcc] problem saving: AddSensor: database is locked
2018-04-28 22:33:00 [DEBUG] [PID-12] server.go parseRollingData:892 [gcc] saved reverse sensor data for wifi-08:3e:5d:13:48:46
2018-04-28 22:33:00 [DEBUG] [PID-12] server.go parseRollingData:881 [gcc] reverse sensor data: {Timestamp:1524954750733 Family:gcc Device:wifi-f0:9f:c2:7d:76:56 Location: Sensors:map[wifi:map[mainhallleft-wifi:-63 cafetv-wifi:-51 kidsroom-wifi:-27 entrance-wifi:-47 mainhallright-wifi:-55]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-28 22:33:05 [WARN] [PID-12] server.go parseRollingData:890 [gcc] problem saving: AddSensor: database is locked
2018-04-28 22:33:05 [DEBUG] [PID-12] server.go parseRollingData:892 [gcc] saved reverse sensor data for wifi-f0:9f:c2:7d:76:56
2018-04-28 22:33:05 [DEBUG] [PID-12] server.go parseRollingData:881 [gcc] reverse sensor data: {Timestamp:1524954750991 Family:gcc Device:wifi-ec:8c:a2:27:b8:38 Location: Sensors:map[wifi:map[mainhallleft-wifi:-57]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-28 22:33:10 [WARN] [PID-12] server.go handlerReverse:819 Set: database is locked
2018-04-28 22:33:10 [INFO] [PID-12] server.go func1:978 172.27.207.39:56890 POST /passive 15.949608689s
2018-04-28 22:33:10 [WARN] [PID-12] server.go parseRollingData:890 [gcc] problem saving: AddSensor: database is locked
2018-04-28 22:33:10 [DEBUG] [PID-12] server.go parseRollingData:892 [gcc] saved reverse sensor data for wifi-ec:8c:a2:27:b8:38
2018-04-28 22:33:10 [DEBUG] [PID-12] server.go parseRollingData:881 [gcc] reverse sensor data: {Timestamp:1524954751053 Family:gcc Device:wifi-2c:76:8a:c5:9c:be Location: Sensors:map[wifi:map[kidsroom-wifi:-75]] GPS:{Latitude:0 Longitude:0 Altitude:0}}
2018-04-28 22:33:15 [WARN] [PID-12] server.go parseRollingData:890 [gcc] problem saving: AddSensor: database is locked
2018-04-28 22:33:15 [DEBUG] [PID-12] server.go parseRollingData:892 [gcc] saved reverse sensor data for wifi-2c:76:8a:c5:9c:be
2018-04-28 22:33:15 [DEBUG] [PID-12] server.go parseRollingData:881 [gcc] reverse sensor data: {Timestamp:1524954750630 Family:gcc Device:wifi-34:8a:ae:e9:9b:2f Location: Sensors:map[wifi:map[entrance-wif

Stopping and starting the docker container for find3 seems to help.

victorhooi commented 6 years ago

Also, when hitting the locations endpoint (api/v1/by_location/<family>?history=5), I'm still seeing frequent timeouts (30 seconds).