Backup error - Connection stalled
The error: Upload attempt failed: Connection to remote server stalled at /usr/local/cpanel/Cpanel/LoggerAdapter.pm line 27
Does this mean that there is a connection issue, such as a firewall block, timeout, connection dropped or is this a problem with WHM itself; setting or bug?
Background
WHM SFTP backup destination fails half of the time on one account but successfully transfers all the others. This account varies on each backup run, so one time it can fail on "abima" and the next time, maybe on "creative62" account, it seems to vary, and happens about 50% of the time. There are 3 accounts on this server. The sender server is running CentOS 7.1, WHM version 11.52.1 (build 3). The backup destination is running CentOS 6.7, WHM version 11.52.1 (build 3). The backup location is /DXLIVE3_backup. Backing up locally has no issues.
The servers are located in separate areas of the UK, with about half of the leg running through a VPN. Both servers are hosts on VMWARE.
-
New The error: Upload attempt failed: Connection to remote server stalled at /usr/local/cpanel/Cpanel/LoggerAdapter.pm line 27
Hello :) Do you notice any error messages in the SFTP logs (/var/log/secure) on the remote destination? Also, are there any additional entries in the transport logs (/usr/local/cpanel/logs/cpbackup_transporter/) on the cPanel server? Thank you.0 -
There are no errrors in /var/log/secure on the destination relating to the sender. During the backup the following is recorded in secure Dec 1 02:00:51 live2 sshd[11483]: Accepted password for root from 62.121.13.124 port 33157 ssh2 Dec 1 02:00:51 live2 sshd[11483]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:00:51 live2 sshd[11483]: subsystem request for sftp Dec 1 02:02:02 live2 sshd[11483]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:02:02 live2 sshd[11483]: pam_unix(sshd:session): session closed for user root Dec 1 02:02:02 live2 sshd[11534]: Accepted password for root from 62.121.13.124 port 4125 ssh2 Dec 1 02:02:03 live2 sshd[11534]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:02:03 live2 sshd[11534]: subsystem request for sftp Dec 1 02:03:08 live2 sshd[11534]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:03:08 live2 sshd[11534]: pam_unix(sshd:session): session closed for user root Dec 1 02:03:09 live2 sshd[11561]: Accepted password for root from 62.121.13.124 port 35991 ssh2 Dec 1 02:03:09 live2 sshd[11561]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:03:09 live2 sshd[11561]: subsystem request for sftp Dec 1 02:03:09 live2 sshd[11561]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:03:09 live2 sshd[11561]: pam_unix(sshd:session): session closed for user root Dec 1 02:03:09 live2 sshd[11575]: Accepted password for root from 62.121.13.124 port 45698 ssh2 Dec 1 02:03:10 live2 sshd[11575]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:03:10 live2 sshd[11575]: subsystem request for sftp Dec 1 02:03:10 live2 sshd[11575]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:03:10 live2 sshd[11575]: pam_unix(sshd:session): session closed for user root Dec 1 02:03:10 live2 sshd[11589]: Accepted password for root from 62.121.13.124 port 55329 ssh2 Dec 1 02:03:10 live2 sshd[11589]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:03:10 live2 sshd[11589]: subsystem request for sftp Dec 1 02:03:28 live2 sshd[11589]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:03:28 live2 sshd[11589]: pam_unix(sshd:session): session closed for user root Dec 1 02:03:28 live2 sshd[11603]: Accepted password for root from 62.121.13.124 port 37857 ssh2 Dec 1 02:03:29 live2 sshd[11603]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:03:29 live2 sshd[11603]: subsystem request for sftp Dec 1 02:05:07 live2 sshd[11603]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:05:07 live2 sshd[11603]: pam_unix(sshd:session): session closed for user root Dec 1 02:05:08 live2 sshd[11643]: Accepted password for root from 62.121.13.124 port 42062 ssh2 Dec 1 02:05:08 live2 sshd[11643]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:05:08 live2 sshd[11643]: subsystem request for sftp Dec 1 02:06:51 live2 sshd[11643]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:06:51 live2 sshd[11643]: pam_unix(sshd:session): session closed for user root Dec 1 02:06:52 live2 sshd[11710]: Accepted password for root from 62.121.13.124 port 22856 ssh2 Dec 1 02:06:52 live2 sshd[11710]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:06:52 live2 sshd[11710]: subsystem request for sftp Dec 1 02:08:27 live2 sshd[11710]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:08:27 live2 sshd[11710]: pam_unix(sshd:session): session closed for user root Dec 1 02:08:27 live2 sshd[11734]: Accepted password for root from 62.121.13.124 port 32903 ssh2 Dec 1 02:08:28 live2 sshd[11734]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:08:28 live2 sshd[11734]: subsystem request for sftp Dec 1 02:08:28 live2 sshd[11734]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:08:28 live2 sshd[11734]: pam_unix(sshd:session): session closed for user root Dec 1 02:08:28 live2 sshd[11748]: Accepted password for root from 62.121.13.124 port 16290 ssh2 Dec 1 02:08:28 live2 sshd[11748]: pam_unix(sshd:session): session opened for user root by (uid=0) Dec 1 02:08:28 live2 sshd[11748]: subsystem request for sftp Dec 1 02:08:29 live2 sshd[11748]: Received disconnect from 62.121.13.124: 11: disconnected by user Dec 1 02:08:29 live2 sshd[11748]: pam_unix(sshd:session): session closed for user root
The transport logs /usr/local/cpanel/logs/cpbackup_transporter/ for the same night contains:[2015-12-01 02:00:50 +0000] info [cpbackup_transporter] Initializing log file [2015-12-01 02:00:50 +0000] info [cpbackup_transporter] cPanel Backup Transporter Queue Daemon started. [2015-12-01 02:00:50 +0000] info [cpbackup_transporter] cpbackup_transporter - started [2015-12-01 02:00:50 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:00:50 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:00:51 +0000] info [cpbackup_transporter] Starting a "copy_system_backup" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:00:51 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:00:51 +0000] info [cpbackup_transporter] Uploading system backup file /backup/2015-12-01/system_files.tar to Live2 [2015-12-01 02:00:51 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/system_files.tar to /DXLIVE3_backup/2015-12-01/system_files.tar for destination: Live2 [2015-12-01 02:02:01 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:02:01 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:02:02 +0000] info [cpbackup_transporter] Starting a "copy_system_backup" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:02:02 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:02:02 +0000] info [cpbackup_transporter] Uploading system backup file /backup/2015-12-01/system_files.tar to Live2 [2015-12-01 02:02:02 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/system_files.tar to /DXLIVE3_backup/monthly/2015-12-01/system_files.tar for destination: Live2 [2015-12-01 02:03:07 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:03:07 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:03:07 +0000] info [cpbackup_transporter] Deleting system backup tar file: /backup/2015-12-01/system_files.tar [2015-12-01 02:03:07 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:03:07 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:03:08 +0000] info [cpbackup_transporter] Starting a "copy" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:03:08 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:03:08 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/accounts/dxlive3.tar.gz to /DXLIVE3_backup/2015-12-01/dxlive3.tar.gz for destination: Live2 [2015-12-01 02:03:08 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:03:08 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:03:09 +0000] info [cpbackup_transporter] Starting a "copy" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:03:09 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:03:09 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/accounts/dxlive3.tar.gz to /DXLIVE3_backup/monthly/2015-12-01/dxlive3.tar.gz for destination: Live2 [2015-12-01 02:03:09 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:03:09 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:03:10 +0000] info [cpbackup_transporter] Starting a "copy" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:03:10 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:03:10 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/accounts/creative62.tar.gz to /DXLIVE3_backup/2015-12-01/creative62.tar.gz for destination: Live2 [2015-12-01 02:03:27 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:03:27 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:03:28 +0000] info [cpbackup_transporter] Starting a "copy" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:03:28 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:03:28 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/accounts/creative62.tar.gz to /DXLIVE3_backup/monthly/2015-12-01/creative62.tar.gz for destination: Live2 [2015-12-01 02:04:58 +0000] warn [cpbackup_transporter] Upload attempt failed: Connection to remote server stalled at /usr/local/cpanel/Cpanel/LoggerAdapter.pm line 27. Cpanel::LoggerAdapter::warn(Cpanel::LoggerAdapter=HASH(0x18d7c50), "Upload attempt failed: Connection to remote server stalled") called at /usr/local/cpanel/Cpanel/Backup/Queue.pm line 497 Cpanel::Backup::Queue::transport_backup::attempt_to_upload_file(Cpanel::Backup::Queue::transport_backup=HASH(0x2034be8), Cpanel::Transport::Files::SFTP=HASH(0x21104a0), "/backup/2015-12-01/accounts/creative62.tar.gz", "/DXLIVE3_backup/monthly/2015-12-01/creative62.tar.gz", Cpanel::LoggerAdapter=HASH(0x18d7c50)) called at /usr/local/cpanel/Cpanel/Backup/Queue.pm line 259 Cpanel::Backup::Queue::transport_backup::process_task(Cpanel::Backup::Queue::transport_backup=HASH(0x2034be8), cPanel::TaskQueue::Task=HASH(0x236efe8), Cpanel::LoggerAdapter=HASH(0x18d7c50)) called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 582 eval {...} called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 585 cPanel::TaskQueue::__ANON__() called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/StateFile.pm line 238 eval {...} called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/StateFile.pm line 238 cPanel::StateFile::Guard::call_unlocked(cPanel::StateFile::Guard=HASH(0x2643430), CODE(0x22dcd10)) called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 590 cPanel::TaskQueue::process_next_task(cPanel::TaskQueue=HASH(0x2110440)) called at /usr/local/cpanel/bin/cpbackup_transporter line 151 eval {...} called at /usr/local/cpanel/bin/cpbackup_transporter line 149 [2015-12-01 02:04:58 +0000] info [cpbackup_transporter] Upload attempt #2 starting for /backup/2015-12-01/accounts/creative62.tar.gz to /DXLIVE3_backup/monthly/2015-12-01/creative62.tar.gz for destination: Live2 [2015-12-01 02:04:58 +0000] warn [cpbackup_transporter] Upload attempt failed: Connection to remote server stalled at /usr/local/cpanel/Cpanel/LoggerAdapter.pm line 27. Cpanel::LoggerAdapter::warn(Cpanel::LoggerAdapter=HASH(0x18d7c50), "Upload attempt failed: Connection to remote server stalled") called at /usr/local/cpanel/Cpanel/Backup/Queue.pm line 497 Cpanel::Backup::Queue::transport_backup::attempt_to_upload_file(Cpanel::Backup::Queue::transport_backup=HASH(0x2034be8), Cpanel::Transport::Files::SFTP=HASH(0x21104a0), "/backup/2015-12-01/accounts/creative62.tar.gz", "/DXLIVE3_backup/monthly/2015-12-01/creative62.tar.gz", Cpanel::LoggerAdapter=HASH(0x18d7c50)) called at /usr/local/cpanel/Cpanel/Backup/Queue.pm line 259 Cpanel::Backup::Queue::transport_backup::process_task(Cpanel::Backup::Queue::transport_backup=HASH(0x2034be8), cPanel::TaskQueue::Task=HASH(0x236efe8), Cpanel::LoggerAdapter=HASH(0x18d7c50)) called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 582 eval {...} called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 585 cPanel::TaskQueue::__ANON__() called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/StateFile.pm line 238 eval {...} called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/StateFile.pm line 238 cPanel::StateFile::Guard::call_unlocked(cPanel::StateFile::Guard=HASH(0x2643430), CODE(0x22dcd10)) called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 590 cPanel::TaskQueue::process_next_task(cPanel::TaskQueue=HASH(0x2110440)) called at /usr/local/cpanel/bin/cpbackup_transporter line 151 eval {...} called at /usr/local/cpanel/bin/cpbackup_transporter line 149 [2015-12-01 02:04:58 +0000] info [cpbackup_transporter] Upload attempt #3 starting for /backup/2015-12-01/accounts/creative62.tar.gz to /DXLIVE3_backup/monthly/2015-12-01/creative62.tar.gz for destination: Live2 [2015-12-01 02:04:58 +0000] warn [cpbackup_transporter] Upload attempt failed: Connection to remote server stalled at /usr/local/cpanel/Cpanel/LoggerAdapter.pm line 27. Cpanel::LoggerAdapter::warn(Cpanel::LoggerAdapter=HASH(0x18d7c50), "Upload attempt failed: Connection to remote server stalled") called at /usr/local/cpanel/Cpanel/Backup/Queue.pm line 497 Cpanel::Backup::Queue::transport_backup::attempt_to_upload_file(Cpanel::Backup::Queue::transport_backup=HASH(0x2034be8), Cpanel::Transport::Files::SFTP=HASH(0x21104a0), "/backup/2015-12-01/accounts/creative62.tar.gz", "/DXLIVE3_backup/monthly/2015-12-01/creative62.tar.gz", Cpanel::LoggerAdapter=HASH(0x18d7c50)) called at /usr/local/cpanel/Cpanel/Backup/Queue.pm line 259 Cpanel::Backup::Queue::transport_backup::process_task(Cpanel::Backup::Queue::transport_backup=HASH(0x2034be8), cPanel::TaskQueue::Task=HASH(0x236efe8), Cpanel::LoggerAdapter=HASH(0x18d7c50)) called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 582 eval {...} called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 585 cPanel::TaskQueue::__ANON__() called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/StateFile.pm line 238 eval {...} called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/StateFile.pm line 238 cPanel::StateFile::Guard::call_unlocked(cPanel::StateFile::Guard=HASH(0x2643430), CODE(0x22dcd10)) called at /usr/local/cpanel/3rdparty/perl/514/lib64/perl5/cpanel_lib/cPanel/TaskQueue.pm line 590 cPanel::TaskQueue::process_next_task(cPanel::TaskQueue=HASH(0x2110440)) called at /usr/local/cpanel/bin/cpbackup_transporter line 151 eval {...} called at /usr/local/cpanel/bin/cpbackup_transporter line 149 [2015-12-01 02:05:06 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:05:06 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:05:07 +0000] info [cpbackup_transporter] Starting a "copy" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:05:07 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:05:07 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/accounts/abima.tar.gz to /DXLIVE3_backup/2015-12-01/abima.tar.gz for destination: Live2 [2015-12-01 02:06:50 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:06:50 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:06:51 +0000] info [cpbackup_transporter] Starting a "copy" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:06:51 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:06:51 +0000] info [cpbackup_transporter] Upload attempt #1 starting for /backup/2015-12-01/accounts/abima.tar.gz to /DXLIVE3_backup/monthly/2015-12-01/abima.tar.gz for destination: Live2 [2015-12-01 02:08:26 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:08:26 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:08:27 +0000] info [cpbackup_transporter] Starting a "prune" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:08:27 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:08:27 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:08:27 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:08:28 +0000] info [cpbackup_transporter] Starting a "prune" operation on the "Live2" destination ID "wgauWR_o7f7tThVuVPTgU2lp". [2015-12-01 02:08:28 +0000] info [cpbackup_transporter] Base path for destination is /DXLIVE3_backup [2015-12-01 02:08:28 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:08:28 +0000] info [cpbackup_transporter] cpbackup_transporter - Processing next task [2015-12-01 02:08:28 +0000] info [cpbackup_transporter] cpbackup_transporter - Checking queue for tasks [2015-12-01 02:08:28 +0000] info [cpbackup_transporter] cpbackup_transporter - Exiting - the queue has been emptied; no more work to do [2015-12-01 02:08:28 +0000] info [cpbackup_transporter] cPanel Backup Transporter Queue Daemon is being stopped.0 -
Do the failed accounts in the transport logs utilize a high amount of disk space? It looks like the connection to the remote server is timing out, indicating an issue with the firewall on one of the servers. Also, increase the timeout values in "WHM >> Backup >> Backup Configuration" for the individual destination and with the "Maximum destination timeout" value. Thank you. 0 -
The 3 accounts take up 800MB, 80MB and 1Mb, which I wouldn't say is particularily large. 'Maximum destination timeout' was already set to 10,000 seconds, which seems high enough for our site-to-site connection. I've increased STFP 'Timeout' from 90 seconds to 240 seconds to see if that makes a difference. I'll report back. 0 -
How were you able to make it accept 10,000 secs? The system only permits up to 300 secs. 0 -
The SFTP 'timout' setting is set to 240 and that has a limit of 300 seconds. I was talking about the 'Maximum destination timeout [] in seconds' value in Backup Configuration -> Global Settings, which needs to be between 300 and 50,000. That is the value that is set to 10,000 0 -
I have done some ping testing between servers and haven't noticed any drops during the night even during the failed ones. More importantly, we had a national campaign going on over the last few weeks which were causing massive load on the server around 9pm every night. Since this finished last week, and I changed the timeout settings; the backup has failed once which is a lot less than usual. I'm not sure why a load at 9pm would cause backups to fail when they start 5 hours later. Lets just hope the backups continue to succeed. 0
Please sign in to leave a comment.
Comments
7 comments