Postal v3 not cleaning up raw messages

[notadevel]

Hi guys,
Got alerted today that our Postal installation has used too much space. It turned out that it is not heeding the message retention limits any longer as set: 60 days or 65 GB after the upgrade to Postal v3. Current version used is 3.1.1 but I could not find any mentions in the later Release notes about that topic, so I guess it is a "unplanned feature".

There are still raw-message tables there from January (more than 60 days, but from Postal 2 at that time) and the database has grown to over 127GB.
I am a bit afraid to just go and delete raw-message tables, I noted that their size is (correctly) indexed in raw_message_sizes and referenced also in the message table.
In the scheduled_tasks table there is a task scheduled "ProcessMessageRetentionScheduledTask" for tomorrow (and not some long passed date), so it appears it is getting processed regularly.
Noted also that some of the messages from back in January do not all have status "sent" in the table (some bounced, some processed, some HoldCancelled). Anyways, these emails are not important any longer and can all go.

Any suggestions?

[willpower232]

The settings page has a retention tab so your first stop should be that page to confirm what the current settings are. I think these are the defaults but I can't remember.

I believe that the tables can be deleted manually if you follow the same steps as the code takes

postal/lib/postal/message_db/provisioner.rb

Lines 114 to 127 in c12f30e

	def remove_raw_tables_older_than(max_age = 30)
	raw_tables(max_age).each do |table|
	remove_raw_table(table)
	end
	end
	#
	# Remove a raw message table
	#
	def remove_raw_table(table)
	@database.query("UPDATE `#{@database.database_name}`.`messages` SET raw_table = NULL, raw_headers_id = NULL, raw_body_id = NULL, size = NULL WHERE raw_table = '#{table}'")
	@database.query("DELETE FROM `#{@database.database_name}`.`raw_message_sizes` WHERE table_name = '#{table}'")
	drop_table(table)
	end

[notadevel]

Well, the limits have been reached long ago. No idea why it did not trigger a cleanup.
Anyways, I could free some space with the manual method, so thank you!

I wonder, is this behavior only on my setup or do others have something similar?

[willpower232]

I would say those limits are quite high, Postal isn't really intended to keep messages very long.

It is possible that the amount of data involved meant the code couldn't keep track of it I guess.

I know that our settings work but there is a bit more competition for it on our setup 😅

[andrzejrostkowski]

Unfortunately we are living with this issue also (v 2.1.4). I can't figure out what patter rules the deletion mechanism. We have much less time and space in the retention tab (screen below) and still have to delete messages from maria db by hand (truncate raw_data tables). It happens mainly on servers with a lot of traffic (one posted package of around 150k emails per 3/4 days). We are not using api - only SMTP to postal. Hope it helps - looking forward for possible fix :)

[willpower232]

I think your numbers are backwards, the meta data needs to be around longer than the raw data. The raw data is the stuff taking up the space in your database.

[andrzejrostkowski]

Hello Will,
Thanks for the replay. I've made the change as You suggested. But after reading above code from Your comment I didn't found it could help in my case, so I've digged a little deeper. In the logs of one of the workers found the following:

[9] [2024-04-19T03:00:00.005] INFO -- : [HHG2XIVFKK] Started processing ProcessMessageRetentionJob job
[9] [2024-04-19T03:00:00.007] INFO -- : [HHG2XIVFKK] Tidying raw messages (by days) for qcard (ID: 1). Keeping 30 days.
[9] [2024-04-19T03:00:00.018] INFO -- : [HHG2XIVFKK] Tidying raw messages (by size) for qcard (ID: 1). Keeping 4048 MB of data.
[9] [2024-04-19T03:00:00.020] INFO -- : [HHG2XIVFKK] Tidying messages for qcard (ID: 1). Keeping 30 days.
[9] [2024-04-19T03:00:00.036] INFO -- : [HHG2XIVFKK] Tidying raw messages (by days) for qcard-wejherowskakarta-pl (ID: 2). Keeping 30 days.
[9] [2024-04-19T03:00:00.051] INFO -- : [HHG2XIVFKK] Tidying raw messages (by size) for qcard-wejherowskakarta-pl (ID: 2). Keeping 2048 MB of data.
[9] [2024-04-19T03:00:00.052] INFO -- : [HHG2XIVFKK] Tidying messages for qcard-wejherowskakarta-pl (ID: 2). Keeping 60 days.
[9] [2024-04-19T03:00:00.093] INFO -- : [HHG2XIVFKK] Tidying raw messages (by days) for qcard-kartalodzianina-pl (ID: 3). Keeping 15 days.
[9] [2024-04-19T03:00:00.093] INFO -- : [HHG2XIVFKK] Tidying raw messages (by size) for qcard-kartalodzianina-pl (ID: 3). Keeping 10000 MB of data.
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK] Mysql2::Error: Incorrect table name ''
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `_query'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `block in query'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `handle_interrupt'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `query'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/database.rb:319:in `query_on_connection'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/database.rb:311:in `block in query'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/mysql.rb:20:in `client'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/database.rb:342:in `with_mysql'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/database.rb:310:in `query'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/provisioner.rb:63:in `drop_table'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/provisioner.rb:124:in `remove_raw_table'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/message_db/provisioner.rb:151:in `remove_raw_tables_until_less_than_size'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/app/jobs/process_message_retention_job.rb:13:in `block in perform'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/activerecord-6.1.7.3/lib/active_record/relation/delegation.rb:88:in `each'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/activerecord-6.1.7.3/lib/active_record/relation/delegation.rb:88:in `each'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/app/jobs/process_message_retention_job.rb:4:in `perform'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/worker.rb:64:in `receive_job'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /opt/postal/app/lib/postal/worker.rb:96:in `block in join_queue'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/consumer.rb:56:in `call'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/channel.rb:1842:in `block in handle_frameset'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/consumer_work_pool.rb:108:in `block (2 levels) in run_loop'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/consumer_work_pool.rb:103:in `loop'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/consumer_work_pool.rb:103:in `block in run_loop'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/consumer_work_pool.rb:102:in `catch'
[9] [2024-04-19T03:00:00.280] WARN -- : [HHG2XIVFKK]    /usr/local/bundle/gems/bunny-2.20.3/lib/bunny/consumer_work_pool.rb:102:in `run_loop'
[9] [2024-04-19T03:00:00.281] INFO -- : [HHG2XIVFKK] Finished processing ProcessMessageRetentionJob job in 0.276035991s

Any suggestion would be great. Maybe I have db corrupted in some way?

MariaDB [postal-server-3]> show tables
    -> ;
+---------------------------+
| Tables_in_postal-server-3 |
+---------------------------+
| clicks                    |
| deliveries                |
| links                     |
| live_stats                |
| loads                     |
| messages                  |
| migrations                |
| raw-2024-04-19            |
| raw_message_sizes         |
| spam_checks               |
| stats_daily               |
| stats_hourly              |
| stats_monthly             |
| stats_yearly              |
| suppressions              |
| webhook_requests          |
+---------------------------+
16 rows in set (0.000 sec)

The raw-2024-04-19 is only 41 mb:

MariaDB [postal-server-3]> SELECT      table_name AS 'Nazwa tabeli',      ROUND(((data_length + index_length) / 1024 / 1024), 2) AS 'Rozmiar w MB'  FROM      information_schema.tables  WHERE      table_schema = 'postal-server-3'  ORDER BY      (data_length + index_length) DESC;
+-------------------+--------------+
| Nazwa tabeli      | Rozmiar w MB |
+-------------------+--------------+
| deliveries        |     16490.00 |
| messages          |      8329.83 |
| raw-2024-04-19    |        41.52 |
| suppressions      |         5.97 |
| stats_hourly      |         1.77 |
| webhook_requests  |         0.11 |
| stats_daily       |         0.08 |
| spam_checks       |         0.06 |
| clicks            |         0.05 |
| links             |         0.05 |
| loads             |         0.03 |
| stats_yearly      |         0.03 |
| raw_message_sizes |         0.03 |
| stats_monthly     |         0.03 |
| migrations        |         0.02 |
| live_stats        |         0.02 |
+-------------------+--------------+
16 rows in set (0.001 sec)

[LotisHunters]

I've got the same issue I think.
Postal isn't respecting raw message size limits, or retention time limits.
I've tried clearing up the raw tables manually but they're just filling up again with hundreds of gigabytes. The database can handle it, but it seems like a big red flag that something isn't running correctly that will cause problems without regular manual intervention to clean it up.

I have a bunch of servers on V3 and they're all exhibiting the same behavior.

[chrisdeeming]

I've got raw message tables dating back to march. Surely the code mentioned by @willpower232 is not running?

Message retention stuff is set to default

[gsommavilla]

I have a mail server with this configuration:

- Number of days that raw message data will be stored: 30 days
- Volume of raw message data that will be stored: 2 GB
- Number of days of message meta data will be available: 60 days

But

• the web app shows that 6.5 GB are used (which is more than the 2 GB set in config)

• I see that in the DB there are tables up to raw-2024-04-08

  there are of course all the other ones:
  raw-2024-04-09
  raw-2024-04-10
  raw-2024-04-11
  raw-2024-04-12
  raw-2024-04-13
  raw-2024-04-14
  ..
  raw-2024-06-19

  Since today is 2024-06-19 and raw storage is 30 days, I can't figure out why there are those tables.

• in the messages table (which I assume are stored the meta data of the emails) I see the oldest message with
  last_delivery_attempt=1709251265.162606 which is GMT Friday 1 March 2024 00:01:05.162
  and this more than 3 months ago.

I have more mail servers whose retention rules are not met;
I will see in the next days what messages and/or raw tables will be deleted and try and see if there is a pattern.

[gsommavilla]

Referring to what I wrote in my previous message: of all the mail servers I have checked, none of them have seen the 'raw' tables or the rows of the 'messages' table being deleted in recent days.

For example, the mail server I mentioned in my previous message still has the table 'raw-2024-04-09' and the more recent raw tables.

I recently updated my postal installation from version 2 to version 3. I know that the 'cron' component is no longer used in version 3. Could this be the reason why the retention rules are not being executed?

[chrisdeeming]

It was a bug and has been fixed in the latest version. I can confirm it fixes the issue.

[willpower232]

This has now been resolved #2970 (comment)