Closed sbe-arg closed 1 year ago
adding more logs
Permissions check (All should be True)
------------------------------------------------
/config/pialert.conf | READ | True
/config/pialert.conf | WRITE | True
/db/pialert.db | READ | True
/db/pialert.db | WRITE | True
------------------------------------------------
[Setup] Attempting to fix permissions.
[Setup] Attempting to fix permissions.
[LOG_LEVEL=debug] 13:38:25 Opening DB
[upgradeDB] Re-creating Settings table
[upgradeDB] Re-creating Parameters table
[2023-06-15 13:38:25] Plugins: Number of dynamically loaded plugins: 6
[Plugins] ---------------------------------------------
[Plugins] display_name: Website monitor
[Plugins] description: This plugin is to monitor status changes of services or websites.
[Plugins] ---------------------------------------------
[Plugins] display_name: UniFi import
[Plugins] description: This plugin is used to import devices from an UNIFI controller.
[Plugins] ---------------------------------------------
[Plugins] display_name: DHCP Leases
[Plugins] description: This plugin is to import devices from dhcp.leases files.
[Plugins] ---------------------------------------------
[Plugins] display_name: Rogue DHCP
[Plugins] description: This plugin is to use NMAP to monitor for rogue DHCP servers.
[Plugins] ---------------------------------------------
[Plugins] display_name: SNMP discovery
[Plugins] description: This plugin is used to discover devices via the arp table(s) of a RFC1213 compliant router or switch.
[Plugins] ---------------------------------------------
[Plugins] display_name: Services (NMAP)
[Plugins] description: This plugin shows all services discovered by NMAP scans.
[API] Updating table_settings.json file in /front/api
[2023-06-15 13:38:26] Config: Imported new config
[Plugins] Check if any plugins need to be executed on run type: once
[API] Updating table_devices.json file in /front/api
[API] Updating table_nmap_scan.json file in /front/api
[API] Updating table_pholus_scan.json file in /front/api
[API] Updating table_events_pending_alert.json file in /front/api
[API] Updating table_plugins_events.json file in /front/api
[API] Updating table_plugins_history.json file in /front/api
[API] Updating table_plugins_objects.json file in /front/api
[API] Updating table_language_strings.json file in /front/api
[API] Updating table_custom_endpoint.json file in /front/api
[2023-06-15 13:38:39] Process: Start
[Plugins] Check if any plugins need to be executed on run type: schedule
[2023-06-15 13:38:25] Check Internet IP:
Retrieving Internet IP:
x.x.x.x
Retrieving previous IP:
x.x.x.x
No changes to perform
Skipping Dynamic DNS update
[LOG_LEVEL=debug] 13:38:40 Scheduler run for pholus: NO
[LOG_LEVEL=debug] 13:38:40 Scheduler run for nmap: NO
[2023-06-15 13:38:25] Scan Devices:
arp-scan start
[LOG_LEVEL=debug] 13:38:51 arp-scan ends
Processing scan results
Saving this IP into the CurrentScan table:192.168.x.x
[LOG_LEVEL=debug] 13:38:51 Print Stats
Devices Detected.......: 10
arp-scan detected..: 8
Pi-hole detected...: +0
New Devices........: 0
Devices in this cycle..: 10
Down Alerts........: 0
New Down Alerts....: 0
New Connections....: 0
Disconnections.....: 1
IP Changes.........: 0
[LOG_LEVEL=debug] 13:38:51 Stats end
Updating DB Info
Sessions Events (connect / discconnect)
[LOG_LEVEL=debug] 13:38:51 Events 1 - Devices down
[LOG_LEVEL=debug] 13:38:51 Events 2 - New Connections
[LOG_LEVEL=debug] 13:38:51 Events 3 - Disconnections
[LOG_LEVEL=debug] 13:38:51 Events 4 - IP Changes
[LOG_LEVEL=debug] 13:38:51 Events end
Creating new devices
[LOG_LEVEL=debug] 13:38:51 New devices - 1 Events
[LOG_LEVEL=debug] 13:38:51 New devices - Insert Connection into session table
[LOG_LEVEL=debug] 13:38:51 New devices - 2 Create devices
[LOG_LEVEL=debug] 13:38:51 New devices - 3 Pi-hole Events
[LOG_LEVEL=debug] 13:38:51 New devices - 4 Pi-hole Create devices
[LOG_LEVEL=debug] 13:38:51 New devices - 5 DHCP Leases Events
[LOG_LEVEL=debug] 13:38:51 New devices - 6 DHCP Leases Create devices
[LOG_LEVEL=debug] 13:38:51 New Devices end
Updating Devices Info
[LOG_LEVEL=debug] 13:38:51 Update devices - 1 Last Connection
[LOG_LEVEL=debug] 13:38:51 Update devices - 2 Clean no active devices
[LOG_LEVEL=debug] 13:38:51 Update devices - 3 LastIP & Vendor
[LOG_LEVEL=debug] 13:38:51 Update devices - 4 Unknown Name
[LOG_LEVEL=debug] 13:38:51 Update devices - 5 Vendor
[LOG_LEVEL=debug] 13:38:51 Update devices end
[LOG_LEVEL=debug] 13:38:51 Resolve devices names
Voiding false (ghost) disconnections
[LOG_LEVEL=debug] 13:38:51 Void - 1 Connect ghost events
[LOG_LEVEL=debug] 13:38:51 Void - 2 Paired events
[LOG_LEVEL=debug] 13:38:51 Void - 3 Disconnect ghost events
[LOG_LEVEL=debug] 13:38:51 Void end
Pairing session events (connection / disconnection)
[LOG_LEVEL=debug] 13:38:51 Pair session - 1 Connections / New Devices
[LOG_LEVEL=debug] 13:38:51 Pair session - 2 Disconnections
[LOG_LEVEL=debug] 13:38:51 Pair session end
Creating sessions snapshot
[LOG_LEVEL=debug] 13:38:51 Sessions Snapshot - 1 Clean
[LOG_LEVEL=debug] 13:38:51 Sessions Snapshot - 2 Insert
[LOG_LEVEL=debug] 13:38:51 Sessions end
Inserting scan results into Online_History
Skipping repeated notifications
[LOG_LEVEL=debug] 13:38:51 Skip Repeated
[LOG_LEVEL=debug] 13:38:51 Skip Repeated end
[Plugins] Check if any plugins need to be executed on run type: always_after_scan
[Plugins] ---------------------------------------------
[Plugins] display_name: Rogue DHCP
[Plugins] CMD: python3 /home/pi/pialert/front/plugins/dhcp_servers/script.py
[Plugins] Timeout: 5
[Plugins]: Pre-Resolved CMD: python3/home/pi/pialert/front/plugins/dhcp_servers/script.py
[Plugins] Executing: python3 /home/pi/pialert/front/plugins/dhcp_servers/script.py
[Plugins] Resolved : ['python3', '/home/pi/pialert/front/plugins/dhcp_servers/script.py']
[2023-06-15 13:38:55] [Plugins]: SUCCESS, received 1 entries
[Plugins] Processing : DHCPSRVS
[Plugins] Existing objects : 1
[Plugins] New and existing events : 1
[Plugins] Found existing object
Check if something to report
No changes to report
[2023-06-15 13:38:55] Notifications: 0
[2023-06-15 13:38:25] Upkeep Database:
Online_History: Delete all but keep latest 150 entries
Optimize Database
Events: Delete all older than 21 days
Plugin Events History: Delete all older than 21 days
Pholus_Scan: Delete all older than 21 days
Pholus_Scan: Delete all duplicates
Nmap_Scan: Delete all duplicates
Shrink Database
[2023-06-15 13:38:58] Last action: cleanup
[2023-06-15 13:38:58] Process: Wait
[API] Updating table_devices.json file in /front/api
[API] Updating table_plugins_history.json file in /front/api
[API] Updating table_custom_endpoint.json file in /front/api
[2023-06-15 13:39:50] Process: Start
[Plugins] Check if any plugins need to be executed on run type: schedule
[LOG_LEVEL=debug] 13:39:50 Scheduler run for pholus: NO
[LOG_LEVEL=debug] 13:39:50 Scheduler run for nmap: NO
[2023-06-15 13:39:50] Process: Wait
[2023-06-15 13:40:54] Process: Start
[Plugins] Check if any plugins need to be executed on run type: schedule
[LOG_LEVEL=debug] 13:40:54 Scheduler run for pholus: NO
[LOG_LEVEL=debug] 13:40:54 Scheduler run for nmap: NO
[2023-06-15 13:40:54] Process: Wait
maybe the db size of 150+mb is normal, if so lets close the issue.
Although is a common pattern the new cpu and memory utilization.
Hey, can you try to run VACUUM on the DB itself?
SSH into the container and:
sudo apt update && sudo apt upgrade -y
sudo apt install sqlite3
sqlite3 /home/pi/pialert/db/pialert.db
sqlite> VACUUM;
Check if the size decreased or not?
same size after vacumm
is 150-200mb an acceptable db size? if is expected I don't really mind. Main worry is if gonna keep growing and clog a few gbs.
Ill keep an eye on it
Hi!
I've added a simple row count for every table into the maintenance page to try to debug issues like these:
You can try using the latest dev image to get basic stats to try to debug this further:
https://registry.hub.docker.com/r/jokobsk/pi.alert_dev
I don't think that a 100MB+ DB size is reasonable for this app
I started fresh, restored a devices csv the db was 1mb the pholus scan run overnight and cpu ram was non existent 2 days later the db is 50mb cpu is 20% and ram is 2gb.
There is a leak somewhere either arp, nmap or pholus
I'd assume it's in Pholus - it's a custom 3rd party script, that is pretty difficult to debug.
Original code from here: https://github.com/aatlasis/Pholus
My modified version with some safeguards on execution run time, etc:
https://github.com/jokob-sk/Pi.Alert/blob/main/pholus/pholus3.py
It's mostly useful to be run once for initial device discovery so I wouldn't recommend running it too often. Still, would be nice to get to the bottom of this or at least to prevent unreasonable DB size growth.
You can check the size of the Pholus_Scan table to see if that's the cause of the DB growth:
select Count(*) from Pholus_Scan
My guess is that the DB size then causes a spike in CPU/RAM usage.
β Anyone reading this thread: Feel free to submit a PR trying to solve this.
Ill test for 2-3 days without pholus and report
Thanks @sbe-arg !
root@pi-alert:/# sqlite3 /home/pi/pialert/db/pialert.db
SQLite version 3.34.1 2021-01-20 14:10:07
Enter ".help" for usage hints.
sqlite> select Count(*) from Pholus_Scan;
10
hope this helps a bit more
Database-Size 45,83 MB
sqlite> SELECT name, total(length(sql)) AS size
FROM sqlite_master
WHERE type='table'
GROUP BY name
ORDER BY size DESC;
Devices|1277.0
Plugins_Objects|900.0
Plugins_History|900.0
Plugins_Events|899.0
Plugins_Language_Strings|398.0
Pholus_Scan|372.0
Events|358.0
Nmap_Scan|336.0
Sessions|330.0
Settings|298.0
Online_History|298.0
CurrentScan|237.0
ScanCycles|187.0
PiHole_Network|186.0
DHCP_Leases|168.0
Parameters|107.0
sqlite_stat1|39.0
sqlite_sequence|38.0
sqlite>
Not sure where the 40mb are actually
Devices|1.25 KB
Plugins_Objects|900 bytes
Plugins_History|900 bytes
Plugins_Events|899 bytes
Plugins_Language_Strings|398 bytes
Pholus_Scan|372 bytes
Events|358 bytes
Nmap_Scan|336 bytes
Sessions|330 bytes
Settings|298 bytes
Online_History|298 bytes
CurrentScan|237 bytes
ScanCycles|187 bytes
PiHole_Network|186 bytes
DHCP_Leases|168 bytes
Parameters|107 bytes
sqlite_stat1|39 bytes
sqlite_sequence|38 bytes
Plugins_History.Index: (115/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 265356
Plugins_History.Plugin: (116/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: DHCPSRVS
Plugins_History.Object_PrimaryID: (117/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: 192.168.1.1
Plugins_History.Object_SecondaryID: (118/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: dns1, dns2
Plugins_History.DateTimeCreated: (119/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: null
Plugins_History.DateTimeChanged: (120/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 728
Most common:
728: 2023-06-16 18:55:37
727: 2023-06-16 18:58:41
726: 2023-06-16 19:01:48
725: 2023-06-16 19:04:55
724: 2023-06-16 19:06:12
723: 2023-06-16 19:09:19
722: 2023-06-16 19:12:25
721: 2023-06-16 19:15:31
720: 2023-06-16 19:18:37
719: 2023-06-16 19:21:43
Least common:
1: 2023-06-18 09:23:56
2: 2023-06-18 09:20:41
3: 2023-06-18 09:17:30
4: 2023-06-18 09:14:20
5: 2023-06-18 09:11:10
6: 2023-06-18 09:08:00
7: 2023-06-18 09:04:49
8: 2023-06-18 09:01:40
9: 2023-06-18 08:58:31
10: 2023-06-18 08:55:22
Plugins_History.Watched_Value1: (121/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: null
Plugins_History.Watched_Value2: (122/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: 192.168.1.x
Plugins_History.Watched_Value3: (123/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: null
Plugins_History.Watched_Value4: (124/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: 192.168.1.1
Plugins_History.Status: (125/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: 0
Plugins_History.Extra: (126/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: 2m00s,255.255.255.0,192.168.1.255
Plugins_History.UserData: (127/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: null
Plugins_History.ForeignKey: (128/144)
Total rows: 265356
Null rows: 0
Blank rows: 0
Distinct values: 1
Most common:
265356: 192.168.1.1
here is some more details... 265356 rows seems out of control.
got by installing
pip3 install sqlite-utils
sqlite-utils analyze-tables /home/pi/pialert/db/pialert.db
although I'm still confused hahaha... ill run without pholus for 48hs
with pholus disabled it stays at 0.5mb in size.
Hi,
Thanks for all the details.
I think this issue is related to the "Known Plugin Issues":
https://github.com/jokob-sk/Pi.Alert/tree/main/front/plugins#-known-issues
Existing plugin objects sometimes not interpreted correctly and a new object is created instead, resulting in duplicate entries.
This is pretty hard to debug, so if you (or anyone reading) have an idea how to prevent this, feel free to submit a PR. I think the bug might be somewhere around this code:
Thanks in advance! j
EDIT: Not sure though why this only manifests when Pholus is enabled as Pholus is not a plugin π€
I agree ill rename it to pholus entry bug so is clear in the issues list
@jokob-sk been running with pholus disabled started with an empty db a few days later. with nmap and dhcprogue plugins is on 45mb
Plugins_Objects.Index: (87/144)
Total rows: 278231
Null rows: 0
Blank rows: 0
Distinct values: 278231
Plugins_Objects.Plugin: (88/144)
Total rows: 278231
Null rows: 0
Blank rows: 0
Distinct values: 2
Most common:
278229: NMAPSRV
2: DHCPSRVS
Plugins_Objects.Object_PrimaryID: (89/144)
Total rows: 278231
Null rows: 0
Blank rows: 0
Distinct values: 16
so the problem is with the plugins itself this does not happen when running with the plugins disabled I think.
need to dig a bit deeper and see what I can find.
Thanks for the ongoing testing!
So we can conclude it is within the plugin system, not related to Pholus (you can change the title of the issue again π)
You can try to change the hash approach to the previous attempt - but from what I remember the issues was still there, maybe there is something else that is causing this bug:
Another workaround would be to add a maintenance task in the upkeep loop that would duplicate the entries, but it would be better to solve the underlying issue π
following
I've implemented an upkeep setting for history entries older than x days. Would be great if someone could test it out on the latest _dev image π
Ill test this during the weekend if I can
π @sbe-arg
Silly me, I re-implemented a previous fix π :
self.sql.execute (f"""DELETE FROM Plugins_History
WHERE DateTimeChanged <= date('now', '{str(DAYS_TO_KEEP_EVENTS)} day')""")
so the original fix didn't work in 100% of cases. My theory is that some plugins don't have DateTimeChanged
specified so the events pile up.
I added one more upkeep limit of 10000
entries in that table by default:
self.sql.execute (f"""DELETE from Plugins_History where "Index" not in (
SELECT "Index" from Plugins_History
order by "Index" desc limit {str(PLUGINS_KEEP_HIST)})""")
This I hope does the trick π€
Gold.
The _dev branch was looking fine after almost 24h or running.
Looking fw testing this new change.
π₯³πThank you!
Closing for now, will reopen if needed π
For those of us not on the dev branch and having issues starting pialert and don't want to nuke our database. Can we run a sqlite3 command to purge the records?
Hey, this should do the trick:
DELETE FROM Plugins_Objects
WHERE rowid > (
SELECT MIN(rowid) FROM Plugins_Objects p2
WHERE Plugins_Objects.Plugin = p2.Plugin
AND Plugins_Objects.Object_PrimaryID = p2.Object_PrimaryID
AND Plugins_Objects.Object_SecondaryID = p2.Object_SecondaryID
AND Plugins_Objects.UserData = p2.UserData)
You can replace the "DELETE" with "SELECT" before running the delete query
EDIT: Added missing )
So this is what I had before.
-rwxrwxrwx 1 www-data www-data 549748736 Sep 4 12:12 pialert.db
-rwxrwxrwx 1 www-data www-data 32768 Sep 4 12:12 pialert.db-shm
-rwxrwxrwx 1 www-data www-data 4260112 Sep 4 12:12 pialert.db-wal
You SQL query wasn't complete had to add );
DELETE FROM Plugins_Objects
WHERE rowid > (
SELECT MIN(rowid) FROM Plugins_Objects p2
WHERE Plugins_Objects.Plugin = p2.Plugin
AND Plugins_Objects.Object_PrimaryID = p2.Object_PrimaryID
AND Plugins_Objects.Object_SecondaryID = p2.Object_SecondaryID
AND Plugins_Objects.UserData = p2.UserData );
It's taking a long time to run; I will let it run and report back.
I could apply CPU limits to the docker container, as the container was taking up 100% of all cores on this machine. Which helped.
version: "3"
services:
pialert:
cpus: "0.5"
After letting it run for a long time the db size went down.
total 92832K
drwxr-xr-x 2 ubuntu ubuntu 4096 Sep 4 13:22 .
drwxr-xr-x 4 root root 4096 Jun 2 02:00 ..
-rwxrwxrwx 1 www-data www-data 95047680 Sep 4 13:22 pialert.db
Instead of 500MB+ it's now 91M
I know you said you haven't tracked this down. Have you thought about a wrapper function for add writes to the database and enable logging so that you can track this down?
Hey @jordantrizz !
There were DB RW debug logs enabled in the past, but that caused the log file to be unreadable and didn't help me to track down this particular bug. There is a
class DB()
wrapper in the database.py file that could be used, but I'd prefer to log this into a separate log file or add another log level.
I also recently commented out a few of those logging lines as the log file became hard to read:
def read(self, query, *args):
"""check the query and arguments are aligned and are read only"""
# mylog('debug',[ '[Database] - Read All: SELECT Query: ', query, " params: ", args])
My priority for the next few weeks is to get the _dev
image into a releasable state - mostly with existing DBs/configs, so this is lower priority for me now. I'd be grateful for any help π
My priority for the next few weeks is to get the _dev image into a releasable state - mostly with existing DBs/configs, so this is lower priority for me now. I'd be grateful for any help π
Sounds good. With a development image, and implementing a logger for database writes and reads to a separate log file would help track this down 100%.
Time's the problem here :)
There is never enough time π
Workaround In release > Closing for now
Describe the issue Great tool as always, I randomly noticed the cpu.memory increase bug as well as my db growing massively lately
My db grew from ~10mb to 160mb since the last update.
I been running this setup pholus on sched nmap on new device arp every 3min smtp plugins (rouge dhcp) retention on everything at 21 days
Paste last few lines from
pialert.log
Paste your
pialert.conf
(remove personal info)Paste your
docker-compose.yml
and.env
(remove personal info)docker-compose.yml
.env
Screenshots If applicable, add screenshots to help explain your problem.