Bug 1925164 - Online backup restarting tarballs even 12 hours after start of process without logging to stdout/console
Summary: Online backup restarting tarballs even 12 hours after start of process withou...
Keywords:
Status: NEW
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Foreman Maintain
Version: 6.8.0
Hardware: Unspecified
OS: Unspecified
medium
medium vote
Target Milestone: Unspecified
Assignee: satellite6-bugs
QA Contact: Gaurav Talreja
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-02-04 14:09 UTC by mithun kalyat
Modified: 2022-06-08 17:54 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2022-05-23 10:23:25 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github pulp pulpcore issues 2809 0 None open Document what actions cause change under /var/lib/pulp 2022-06-08 16:24:40 UTC

Description mithun kalyat 2021-02-04 14:09:47 UTC
Without creating any output to the logging, process list that the tar command to create the pulp_data.tar is starting 12 hours after the online backup process is started.Log output of the backup process does not show anything:

--------
Creating backup folder /backup/satellite-backup-2021-01-25-01-00-04   ESC[32mESC[1m[OK]ESC[0m
--------------------------------------------------------------------------------
Check if the directory exists and is writable:                        ESC[32mESC[1m[OK]ESC[0m
--------------------------------------------------------------------------------
Generate metadata:

Collecting metadata
Collecting system release info
Collecting list of plugins
Collecting list of proxy features
Collecting installed RPMs
Saving metadata to metadata.yml                                       ESC[32mESC[1m[OK]ESC[0m
--------------------------------------------------------------------------------
Backup config files:

Collecting config files to backup                                     ESC[32mESC[1m[OK]ESC[0m
--------------------------------------------------------------------------------
Backup Pulp data:

Collecting Pulp data
(END)


From /var/log/foreman-maintain/foreman-maintain.log, it looks like retry is not limited to just a few (e.g. 3) times. With the pulp data tarball easily can take a few hours to create it quickly sums up in the time. See e.g. the 2021-01-09 where it retries for the 8x at 23:48UTC for a backup that was started at 01:00UTC. And the next backup would almost be starting again:
--------
root@satellite:/usr/share/gems/gems/foreman_maintain-0.6.14# grep 'Retrying...' /var/log/foreman-maintain/foreman-maintain.log
I, [2021-01-07 04:05:52+0000 #15496]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-07 07:09:33+0000 #15496]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-07 10:15:07+0000 #15496]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-07 13:20:38+0000 #15496]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-07 16:23:02+0000 #15496]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-07 18:58:16+0000 #15496]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-07 22:09:45+0000 #15496]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 03:52:20+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 06:53:22+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 10:14:38+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 13:20:34+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 16:16:09+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 19:11:48+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 22:10:59+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-08 23:45:44+0000 #24538]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 04:11:53+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 07:04:24+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 10:10:33+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 13:08:29+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 16:04:53+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 19:11:44+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 22:10:59+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-09 23:48:04+0000 #17694]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-10 04:17:16+0000 #10799]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-10 07:20:34+0000 #10799]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-10 10:23:16+0000 #10799]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-10 13:20:47+0000 #10799]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-10 16:16:36+0000 #10799]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-10 19:21:21+0000 #10799]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-11 03:57:31+0000 #22512]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-11 06:52:18+0000 #22512]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...
I, [2021-01-11 10:05:43+0000 #22512]  INFO -- : Data in /var/lib/pulp changed during backup. Retrying...


- Logging of the backup process is too less to analyze/troubleshoot why commands are failing/restart and/or taken that long.

- Restarting a command 12 Hours after backup is also not good anymore for predictability. It does not match the real scheduled backup time (01:00am UTC) I planned as user.

Comment 2 Amit Upadhye 2022-05-23 10:23:25 UTC
Hello,

From Satellite 6.10 onward there is newer qpid stack with Pulp 3 which should help to avoid this kind of situations. Accordingly I am closing this bugzilla.

If in case you see similar issue with newer Satellite versions then request to raise new bug for same.

Thank You,
Amit Upadhye.

Comment 4 Ian Ballou 2022-06-08 16:24:41 UTC
After chatting with folks from Pulp, they mentioned that they would like to write a new Pulpcore documentation section about filesystem changes in /var/lib/pulp.  There are numerous ways that file changes can occur, so having official documentation would be best.  Since the documentation will be published in Pulp terms, we can help translate it into Satellite (6.10+) terms once it's done.

I've linked the upstream Pulpcore issue requesting for the documentation.

Shall we reopen the issue for the documentation update?

Comment 5 Amit Upadhye 2022-06-08 17:54:25 UTC
Hello,

As per the discussion with Katello and Pulp team there could be occurrences of files getting modified however the situations will be lesser in number. We are working with Pulp team to get the details about when and how it happens.

I am reopening the bugzilla however its low priority and would be worked on as per general bugzilla prioritization process.

Regards,
Amit Upadhye.


Note You need to log in before you can comment on or make changes to this bug.