Backblaze B2: transport hangs with "Deep recursion on subroutine"

[phil99]

Since the upgrade to WHM 96, we are regularly seeing the following in the cpbackup_transporter logs:

[2021-05-19 02:27:53 +0100] info [cpbackup_transporter] Upload attempt #1 starting for /backup_cpanel/2021-05-19/accounts/account.tar.gz to backup_cpanel/2021-05-19/accounts/account.tar.gz for destination:  Backblaze B2
[2021-05-19 03:18:53 +0100] info [cpbackup_transporter] Deep recursion on subroutine "Cpanel::Transport::Files::Backblaze::_do_request" at /usr/local/cpanel/Cpanel/Transport/Files/Backblaze.pm line 297.
[2021-05-19 03:18:54 +0100] info [cpbackup_transporter] Deep recursion on subroutine "Cpanel::Transport::Files::Backblaze::_do_request" at /usr/local/cpanel/Cpanel/Transport/Files/Backblaze.pm line 269.

(The actual account name has been replaced with "account").

At this point, the transport process hangs.

So far, this has always occurred when transporting one particular account.


On a related note: when this occurs we stop the transporter process with:

/usr/local/cpanel/bin/cpbackup_transporter --stop

which reports:

Graceful shutdown of cPanel Backup Transporter Queue Daemon requested  -  complete

At this point, the remaining account.tar.gz files are still present in the backup directory, including the one on which the transport process hung. When we restart the cpbackup_transporter process, the transport process continues as expected and most of the remaining files are uploaded. However, no attempt is made to upload the file on which the transport process hung, and the file is silently deleted.

Should the transport process not realise that it had not successfully uploaded this file? Obviously, in this case at least, it might lead to a loop with the transport continually failing, but it might be appropriate in other circumstances?

Thanks.

 

[cPRex]

Hey there! We've seen this error a few times in the past (I see 8 entries for it in the entire history of our ticket system) and each of those incidents ended with the user reaching out to Backblaze to resolve the issue. Was there also possible a 500 after shortly after the "Deep recursion on subroutine" lines?

 

[phil99]

Hi, no the next entry in the log is over 3 hours later when the process was shutdown:

[2021-05-19 06:33:23 +0100] info [cpbackup_transporter] Graceful shutdown due to SIGHUP

 

[cPRex]

That's definitely odd - could you submit a ticket to our team so we can look into this?

 

[quanin]

I own one of those 8 tickets in your history, @cPRex. I just disabled the B2 entry, because it only started doing it after an upgrade to 96 and Backblaze hadn't made any changes in the 24 hours previous. If CPanel ever gets around to fixing it, I'll reenable it.

 

[cPRex]

The 8 tickets are spread out since 2017, so the issue doesn't seem to be related to a particular update. If you have a recent ticket in with us you can always reply or open a new one so we can do some additional testing, but I'm not seeing any specific issues that would relate to this issue on my end.

 

[phil99]

Thanks, ticket submitted: #94327364

 

[cPRex]

Thanks for posting the number. I'm following along with this on my end and I'll be sure to keep this thread updated.

 

[cPRex]

It looks like the issue is no longer happening as both your automated backups and our team were no longer able to reproduce the issue. If you do hear anything from Backblaze, please post that info here!

 

[cPRex]

Our team has set up some additional debugging on the system to see if we can get more details. I'll be sure to post here if we find more.

 

[VBX Co]

Just wanted to report that I'm seeing the exact same thing. Not on every backup, sometimes there will be several successful backups, but then a failed/partial backup with the same error reported in the transport log file - with the two same line numbers 297 & 296.

Backup process still active and backup files still on server drive ... which, over two backups is enough to use up most all of the available space on the server (which is how I became aware of it when customers reported the server as unresponsive).

I've been running backups to Backblaze like clockwork for years with literally zero problems until recently.

Would love to know if this is a cPanel issue and if so, what the fix is.

Thanks

 

[VBX Co]

Happened again last night:

[2021-06-13 06:15:32 +0100] info [cpbackup_transporter] cpbackup_transporter - Processing next task
[2021-06-13 06:15:32 +0100] info [cpbackup_transporter] Instantiating Object
[2021-06-13 06:15:32 +0100] info [cpbackup_transporter] Starting a "copy" operation on the "BBlaze" destination ID "*************************".
[2021-06-13 06:15:32 +0100] info [cpbackup_transporter] Base path for destination is backup
[2021-06-13 06:15:32 +0100] info [cpbackup_transporter] Validating destination path backup/2021-06-13/accounts/
[2021-06-13 06:15:34 +0100] info [cpbackup_transporter] Path exists
[2021-06-13 06:15:34 +0100] info [cpbackup_transporter] Uploading account backup /backup/2021-06-13/accounts/eee2222.tar.gz to backup/2021-06-13/accounts/eee2222.tar.gz (from 2021-06
-13/accounts/eee2222.tar.gz)
[2021-06-13 06:15:34 +0100] info [cpbackup_transporter] Attempting to upload /backup/2021-06-13/accounts/eee2222.tar.gz to backup/2021-06-13/accounts/eee2222.tar.gz for destination:
BBlaze
[2021-06-13 06:15:34 +0100] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2021-06-13/accounts/eee2222.tar.gz to backup/2021-06-13/accounts/eee2222.tar.gz for des
tination:  BBlaze
[2021-06-13 07:09:43 +0100] info [cpbackup_transporter] Deep recursion on subroutine "Cpanel::Transport::Files::Backblaze::_do_request" at /usr/local/cpanel/Cpanel/Transport/Files/Ba
ckblaze.pm line 297.
[2021-06-13 07:09:43 +0100] info [cpbackup_transporter] Deep recursion on subroutine "Cpanel::Transport::Files::Backblaze::_do_request" at /usr/local/cpanel/Cpanel/Transport/Files/Ba
ckblaze.pm line 269.

 

[phil99]

cPanel are of the opinion that the "Deep recursion" errors are related to the 500 transport errors [1]. If you look in that thread, there is a link to a cPanel support case which contains a patch you could try until a fix rolls out.

[1] SOLVED - CPANEL-36050 - Backblaze B2: Backup transport errors

 

[miketx]

Same. This is killing us...would love an update.
We have a case: 37077

Any ETA?

 

[cPRex]

@miketx - CPANEL-37077 is marked as a duplicate of CPANEL-36050, which was linked above. When 36050 is fixed, it will fix related issues as well, which is planned to be included in 96.0.11.

 

[VBX Co]

Thanks - glad to know it's not just me (there seem to be quite a few others experiencing the same problem) - and glad to know a fix is coming.

 

[High Voltage]

Affecting me as well, 3 times now in the last couple of months.
Glad to know a fix is on the way. Yes my logs show a 500 error as the first sign anything has gone wrong.

 

[VBX Co]

Okay, 96.0.11 installed and will watch over the next couple of weeks to see how it goes - fingers crossed

 

[cPRex]

Some users are still reporting this happening in 96.0.11, and we have opened CPANEL-37482 for tracking of this issue. If you see this happening, please open a ticket with our team so we can investigate the issue directly on your machine.

 

[VBX Co]

Okay, 96.0.11 installed and will watch over the next couple of weeks to see how it goes - fingers crossed

I can report that I have not had any further issues since the update. Resolved for me.