[Box Backup] bbackupctl always fails when run from crontab. Manual always OK?

Thu, 24 Aug 2006 07:02:54 -0700

On 8/24/06 3:14 AM, Tobias Balle-Petersen wrote:
> Hello...
>
> As expected, the scond time bbackupctl was  run as a cronjob it
> failed.  Log from the client  seen below.
>
> I have just performed a "/usr/local/bin/bbackupctl -c
> /etc/box_minimoni/bbackupd.conf reload"
> I expect this to allow the next run started from the crontab to be run
> without errors. Will report back.
>
> Thanks,
> Tobias
>
> Log from client:
>
[snip]
> Aug 24 10:21:08 yoiko bbackupd[11514]: TRACE: Diff: 12288 new bytes
> found, 20 old blocks used\n
> Aug 24 10:21:08 yoiko bbackupd[11514]: TRACE: Suspended timer for file
> diff control\n
> Aug 24 10:21:08 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 2333\n
> Aug 24 10:23:29 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 3244\n
> ..........
> Aug 24 11:06:37 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 2950 to 4406\n
> Aug 24 11:07:09 yoiko bbackupd[11514]: TRACE: Initiated timer for file
> diff control\n
> Aug 24 11:07:13 yoiko bbackupd[11514]: TRACE: Diff: 117248 new bytes
> found, 3833 old blocks used\n
> Aug 24 11:07:13 yoiko bbackupd[11514]: TRACE: Suspended timer for file
> diff control\n
> Aug 24 11:07:13 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 2617\n
> Aug 24 11:07:13 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 2617 to 3596\n
> Aug 24 11:07:13 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 3596 to 5415\n
> Aug 24 11:07:30 yoiko bbackupd[11514]: TRACE: Initiated timer for file
> diff control\n
> Aug 24 11:07:37 yoiko bbackupd[11514]: TRACE: Diff: 0 new bytes found,
> 1440 old blocks used\n
> Aug 24 11:07:37 yoiko bbackupd[11514]: TRACE: Suspended timer for file
> diff control\n
> Aug 24 11:08:03 yoiko bbackupd[11514]: TRACE: Initiated timer for file
> diff control\n
> Aug 24 11:08:04 yoiko bbackupd[11514]: TRACE: Diff: 14336 new bytes
> found, 725 old blocks used\n
> Aug 24 11:08:04 yoiko bbackupd[11514]: TRACE: Suspended timer for file
> diff control\n
> Aug 24 11:08:04 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 3244\n
> Aug 24 11:08:04 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 3244 to 4998\n
> Aug 24 11:08:04 yoiko bbackupd[11514]: TRACE: Initiated timer for file
> diff control\n
> Aug 24 11:08:05 yoiko bbackupd[11514]: TRACE: Diff: 11776 new bytes
> found, 894 old blocks used\n
> Aug 24 11:08:05 yoiko bbackupd[11514]: TRACE: Suspended timer for file
> diff control\n
> Aug 24 11:08:05 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 3244\n
> Aug 24 11:08:05 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 3244 to 5133\n
> Aug 24 11:11:23 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 2849\n
> Aug 24 11:11:23 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 2849 to 5025\n
> Aug 24 11:11:27 yoiko bbackupd[11514]: TRACE: Initiated timer for file
> diff control\n
> Aug 24 11:11:27 yoiko bbackupd[11514]: TRACE: Diff: 880838 new bytes
> found, 152 old blocks used\n
> Aug 24 11:11:27 yoiko bbackupd[11514]: TRACE: Suspended timer for file
> diff control\n
> Aug 24 11:11:27 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 2601\n
> Aug 24 11:11:27 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 2601 to 4777\n
> Aug 24 11:11:27 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 2606\n
> ...................
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 1068 to 3244\n
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Reallocating
> EncodingBuffer from 3244 to 5413\n
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/Novo
> Nordisk/Recruitment/recruitment_ms\n
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/Novo
> Nordisk/Recruitment/recruitment_tos\n
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/Novo
> Nordisk/Recruitment/recruitment2_ms\n
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/Novo Nordisk/Recruitment/re.kmo\n
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/Novo Nordisk/Recruitment/recruitment
> transport fredag\n
> Aug 24 11:16:19 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/Novo
> Nordisk/Recruitment/re.transp.mandag\n
> Aug 24 11:20:28 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/Medicon\n
> Aug 24 11:20:28 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/clients/MOUNT\n
> Aug 24 11:20:44 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/guests/Bergen Bybane\n
> Aug 24 11:20:44 yoiko bbackupd[11514]: TRACE: Deleted directory record
> for /Volumes/raidA/files/guests/Library1\n
Seems like the problem occurs here... More than 20 minutes with no
logging. Just looking at directories, I guess...
> Aug 24 11:41:58 yoiko bbackupd[11514]: TRACE: Exception thrown:
> ConnectionException(Conn_TLSReadFailed) at SocketStreamTLS.cpp(361)\n
> Aug 24 11:41:58 yoiko bbackupd[11514]: TRACE: Exception thrown:
> ConnectionException(Conn_TLSWriteFailed) at SocketStreamTLS.cpp(426)\n
> Aug 24 11:41:59 yoiko bbackupd[11514]: Exception caught (Connection
> TLSReadFailed 7/34), reset state and waiting to retry...
> Aug 24 11:42:09 yoiko bbackupd[11514]: File statistics: total file
> size uploaded 13410118455, bytes already on server 341406646, encoded
> size 9996343505
> Aug 24 11:42:09 yoiko bbackupd[11514]: TRACE: Wait on command socket,
> delay = 1024000000\n
> Aug 24 11:59:13 yoiko bbackupd[11514]: TRACE: Wait on command socket,
> delay = 1024000000\n
>
It seems from the logs that the error occurs while scanning the client
directories. I don't know if the directory-scanning code has been
changed to use the keep-alives. Does anyone know if the keep-alives are
only implemented in file-diffing, or if they are also used in the
overall directory scanning? Gary?

Are you using the (I forget what the feature is called) Berkeley DB
local cache of file state? I don't know if this could have anything to
do with what's going on...

As for why the manual works, and the cron fails, I have no idea...

Thanks,
Per

-- 
Per Reedtz Thomsen | Reedtz Consulting, LLC | F: 209 883 4119
V: 209 883 4102    |   pthomsen@reedtz.com  | C: 209 996 9561
GPG ID: 1209784F   |  Yahoo! Chat: pthomsen | AIM: pthomsen