Open menos08642 opened 1 year ago
For the past two weeks my install has been stuck in this cycle where it validates file information (to 115%) and then restarts. The relevent part of service.log is here r@414226550[ timestamp=1670046168300, txValid=false, bmfValid=false, propsValid=false, pathsValid=false, throttler=1000/1000] [12.02.22 23:49:27.826 INFO er1WeDftWkr0 ackup.manifest.ClientSyncHandler] SYNC::BT-777062302159407600>42: Accepting backup files and file history - done=false, progress=SyncProgressStats[files=true, current=2176321, total=1887749 (115.3%)], num=2; ClientSyncHandler@414226550[ timestamp=1670046168300, txValid=false, bmfValid=false, propsValid=false, pathsValid=false, throttler=1000/1000] [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::stopRestore(): idPair=777062302159407600>42, selectedForRestore=false, event=STOP_REQUESTED canceled=false [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::Not selected for restore [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::0 pending restore canceled [12.02.22 23:49:27.893 INFO DefaultGroup com.code42.backup.BackupEntityV1] BC[777062302159407600>42:: Setting keepBlockState=0 during reset(); BC[777062302159407600>42, sameOwner=f, backupConnected=f, authorized=f, usingForBackup=t, backupNotReadyCode=NOT_AVAILABLE, backingUp=f, validating=t, closing=f, keepBlockState=0, con=2022-12-02T23:42:47:985, val=2022-12-02T23:49:27:826, readyCheckTime=2022-12-02T23:42:47:985, MM[BT 777062302159407600>42: openCount=1, initialized = true, dataFiles.open = true, /usr/local/crashplan/cache/42], session=null, hosted=t, hostedCloud=t, replacing=t, selectedForBackup=f, selectedForRestore=f, validationNeeded=f, backupUsageTime=2022-12-02T23:42:48:060, cacheMaintenanceState=null, restoreUtil=BackupClientRestoreDelegate [restoreEnv=null, selectedForRestore=false, remoteRestoreStats=RestoreStats[BT sourceId = 777062302159407600, targetId = 42, restoreId = 0, selectedForRestore = false, restoring = false, completed = false, completedTimeInMillis = null, stopwatch = 6min 43sec, numFilesToRestore = 0, numBytesToRestore = 0, numFilesRestored = 0, numBytesRestored = 0, %complete = 100.00%, receiveRateInBytesPerSec(B/s) = 0.000, sendRateInBytesPerSec(B/s) = 0.000, estimatedTimeRemaining = 0.000, fileNumBytesToRestore = 0, fileNumBytesRestored = 0, %completeCurrentFile = 100.00%, numSessionFilesRestored = 0, numSessionBytesRestored = 0, problemCount = 0], pendingRestoresCount=0], BackupQueue[777062302159407600>42, running=f, #tasks=0, sets=[BackupFileTodoSet[backupSetId=1, guid=42, doneLoadingFiles=f, doneLoadingTasks=f, FileTodoSet@319974726[ path = /usr/local/crashplan/cache/cpft1_42, closed = false, dataSize = 7623673, headerSize = 0], numTodos = 44807, numBytes = 1299372381986]], BackupFileTodoSet[backupSetId=1002652120906781217, guid=42, doneLoadingFiles=t, doneLoadingTasks=f, FileTodoSet@241535624[ path = /usr/local/crashplan/cache/cpft1002652120906781217_42, closed = false, dataSize = 12, headerSize = 0], numTodos = 0, numBytes = 0]]], env=null, todow=TodoWorker@1492425566[ threadName = BQTodoWkr-42, stopped = true], taskw=TaskWorker@865435227[ threadName = BQTaskWrk-42, stopped = true], lastTask=null] ]; [12.02.22 23:49:27.893 INFO DefaultGroup code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::Shutting down: size=0, #busy=0, #workers=1 [12.02.22 23:49:27.894 INFO DefaultGroup code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567893, queueSize=1, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, overflowFlag=false, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, queueSize=0, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, durationQueued=1, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, result=RESULT_NOT_SET, duration=0, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::All background workers have shutdown And then it starts all over again. I've tried blowing the local cache and config away and reinstalling but I get the same behavior. What next can I try?
r@414226550[ timestamp=1670046168300, txValid=false, bmfValid=false, propsValid=false, pathsValid=false, throttler=1000/1000] [12.02.22 23:49:27.826 INFO er1WeDftWkr0 ackup.manifest.ClientSyncHandler] SYNC::BT-777062302159407600>42: Accepting backup files and file history - done=false, progress=SyncProgressStats[files=true, current=2176321, total=1887749 (115.3%)], num=2; ClientSyncHandler@414226550[ timestamp=1670046168300, txValid=false, bmfValid=false, propsValid=false, pathsValid=false, throttler=1000/1000] [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::stopRestore(): idPair=777062302159407600>42, selectedForRestore=false, event=STOP_REQUESTED canceled=false [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::Not selected for restore [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::0 pending restore canceled [12.02.22 23:49:27.893 INFO DefaultGroup com.code42.backup.BackupEntityV1] BC[777062302159407600>42:: Setting keepBlockState=0 during reset(); BC[777062302159407600>42, sameOwner=f, backupConnected=f, authorized=f, usingForBackup=t, backupNotReadyCode=NOT_AVAILABLE, backingUp=f, validating=t, closing=f, keepBlockState=0, con=2022-12-02T23:42:47:985, val=2022-12-02T23:49:27:826, readyCheckTime=2022-12-02T23:42:47:985, MM[BT 777062302159407600>42: openCount=1, initialized = true, dataFiles.open = true, /usr/local/crashplan/cache/42], session=null, hosted=t, hostedCloud=t, replacing=t, selectedForBackup=f, selectedForRestore=f, validationNeeded=f, backupUsageTime=2022-12-02T23:42:48:060, cacheMaintenanceState=null, restoreUtil=BackupClientRestoreDelegate [restoreEnv=null, selectedForRestore=false, remoteRestoreStats=RestoreStats[BT sourceId = 777062302159407600, targetId = 42, restoreId = 0, selectedForRestore = false, restoring = false, completed = false, completedTimeInMillis = null, stopwatch = 6min 43sec, numFilesToRestore = 0, numBytesToRestore = 0, numFilesRestored = 0, numBytesRestored = 0, %complete = 100.00%, receiveRateInBytesPerSec(B/s) = 0.000, sendRateInBytesPerSec(B/s) = 0.000, estimatedTimeRemaining = 0.000, fileNumBytesToRestore = 0, fileNumBytesRestored = 0, %completeCurrentFile = 100.00%, numSessionFilesRestored = 0, numSessionBytesRestored = 0, problemCount = 0], pendingRestoresCount=0], BackupQueue[777062302159407600>42, running=f, #tasks=0, sets=[BackupFileTodoSet[backupSetId=1, guid=42, doneLoadingFiles=f, doneLoadingTasks=f, FileTodoSet@319974726[ path = /usr/local/crashplan/cache/cpft1_42, closed = false, dataSize = 7623673, headerSize = 0], numTodos = 44807, numBytes = 1299372381986]], BackupFileTodoSet[backupSetId=1002652120906781217, guid=42, doneLoadingFiles=t, doneLoadingTasks=f, FileTodoSet@241535624[ path = /usr/local/crashplan/cache/cpft1002652120906781217_42, closed = false, dataSize = 12, headerSize = 0], numTodos = 0, numBytes = 0]]], env=null, todow=TodoWorker@1492425566[ threadName = BQTodoWkr-42, stopped = true], taskw=TaskWorker@865435227[ threadName = BQTaskWrk-42, stopped = true], lastTask=null] ]; [12.02.22 23:49:27.893 INFO DefaultGroup code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::Shutting down: size=0, #busy=0, #workers=1 [12.02.22 23:49:27.894 INFO DefaultGroup code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567893, queueSize=1, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, overflowFlag=false, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, queueSize=0, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, durationQueued=1, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, result=RESULT_NOT_SET, duration=0, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::All background workers have shutdown
For the past two weeks my install has been stuck in this cycle where it validates file information (to 115%) and then restarts. The relevent part of service.log is here
r@414226550[ timestamp=1670046168300, txValid=false, bmfValid=false, propsValid=false, pathsValid=false, throttler=1000/1000] [12.02.22 23:49:27.826 INFO er1WeDftWkr0 ackup.manifest.ClientSyncHandler] SYNC::BT-777062302159407600>42: Accepting backup files and file history - done=false, progress=SyncProgressStats[files=true, current=2176321, total=1887749 (115.3%)], num=2; ClientSyncHandler@414226550[ timestamp=1670046168300, txValid=false, bmfValid=false, propsValid=false, pathsValid=false, throttler=1000/1000] [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::stopRestore(): idPair=777062302159407600>42, selectedForRestore=false, event=STOP_REQUESTED canceled=false [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::Not selected for restore [12.02.22 23:49:27.893 INFO DefaultGroup tore.BackupClientRestoreDelegate] BC::0 pending restore canceled [12.02.22 23:49:27.893 INFO DefaultGroup com.code42.backup.BackupEntityV1] BC[777062302159407600>42:: Setting keepBlockState=0 during reset(); BC[777062302159407600>42, sameOwner=f, backupConnected=f, authorized=f, usingForBackup=t, backupNotReadyCode=NOT_AVAILABLE, backingUp=f, validating=t, closing=f, keepBlockState=0, con=2022-12-02T23:42:47:985, val=2022-12-02T23:49:27:826, readyCheckTime=2022-12-02T23:42:47:985, MM[BT 777062302159407600>42: openCount=1, initialized = true, dataFiles.open = true, /usr/local/crashplan/cache/42], session=null, hosted=t, hostedCloud=t, replacing=t, selectedForBackup=f, selectedForRestore=f, validationNeeded=f, backupUsageTime=2022-12-02T23:42:48:060, cacheMaintenanceState=null, restoreUtil=BackupClientRestoreDelegate [restoreEnv=null, selectedForRestore=false, remoteRestoreStats=RestoreStats[BT sourceId = 777062302159407600, targetId = 42, restoreId = 0, selectedForRestore = false, restoring = false, completed = false, completedTimeInMillis = null, stopwatch = 6min 43sec, numFilesToRestore = 0, numBytesToRestore = 0, numFilesRestored = 0, numBytesRestored = 0, %complete = 100.00%, receiveRateInBytesPerSec(B/s) = 0.000, sendRateInBytesPerSec(B/s) = 0.000, estimatedTimeRemaining = 0.000, fileNumBytesToRestore = 0, fileNumBytesRestored = 0, %completeCurrentFile = 100.00%, numSessionFilesRestored = 0, numSessionBytesRestored = 0, problemCount = 0], pendingRestoresCount=0], BackupQueue[777062302159407600>42, running=f, #tasks=0, sets=[BackupFileTodoSet[backupSetId=1, guid=42, doneLoadingFiles=f, doneLoadingTasks=f, FileTodoSet@319974726[ path = /usr/local/crashplan/cache/cpft1_42, closed = false, dataSize = 7623673, headerSize = 0], numTodos = 44807, numBytes = 1299372381986]], BackupFileTodoSet[backupSetId=1002652120906781217, guid=42, doneLoadingFiles=t, doneLoadingTasks=f, FileTodoSet@241535624[ path = /usr/local/crashplan/cache/cpft1002652120906781217_42, closed = false, dataSize = 12, headerSize = 0], numTodos = 0, numBytes = 0]]], env=null, todow=TodoWorker@1492425566[ threadName = BQTodoWkr-42, stopped = true], taskw=TaskWorker@865435227[ threadName = BQTaskWrk-42, stopped = true], lastTask=null] ]; [12.02.22 23:49:27.893 INFO DefaultGroup code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::Shutting down: size=0, #busy=0, #workers=1 [12.02.22 23:49:27.894 INFO DefaultGroup code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567893, queueSize=1, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, overflowFlag=false, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, queueSize=0, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, durationQueued=1, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, itemType=class com.code42.queue.BackgroundWorkQueue$StopWork, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::time=1670046567894, result=RESULT_NOT_SET, duration=0, sessionID=StopWork [12.02.22 23:49:27.894 INFO 46168300::-1 code42.queue.BackgroundWorkQueue] BWQ-Sync-1670046168300::All background workers have shutdownAnd then it starts all over again. I've tried blowing the local cache and config away and reinstalling but I get the same behavior. What next can I try?