›

The rsync channel has been blocked for more than 120 seconds

Germo GörtzGermo Görtz
edited September 2014 in Acrosync for Windows
I got this error:

2014/09/21 21:59:11    The rsync channel has been blocked for more than 120 seconds (read:-1:1:1:1:0:64000:0:64000:0:0:0:1)

would be fine if Acrosync would not stop after 120 sec or if there would be a way where the user can set the tie limit when acrosunc should stop in this case.

Comments

  • Germo GörtzGermo Görtz
    other jobs in the Queue are not started after this happens. Acrosync stops, but in the status bar the progress bar is still there and the information "Snapshoting C:" 
    But on the page for this job it is enabled (could be manually restarted?)
    And the second job (in the queue "D:") dosn't start.
  • gchen
    Are you sure the second job didn't run?  In my test, the second job always started and finished successfully after the error message was dismissed, whether the job was scheduled before or after the error.

    If there is nothing to upload then there will be no log messages except the one saying "performing a full backup of ...".  You can turn on the Verbose logging option on the Log tab to see the actual command performed by the job.

    So I think the bug here is the progress bar remaining visible after the error.  It is by design that when an error happens, the job will be stopped with the profile tab enabled.

  • Germo GörtzGermo Görtz
    edited September 2014
    you are right, there was still a window with the error message in the background which I did not see. I clicked OK and not it's OK.
  • gchen
    The real bug here is that the entire main window should not be enabled when the error message box is active.  The error message box should be modal -- that is, the only thing you can do is to click the ok button to dismiss the error message box.  After the error message box is dismissed, the  the status bar will be updated, and then the progress bar disappears, and the next job in the queue starts.

    I'll make the error message box modal in the next update.
  • DaVig
    Hi folks,

    I'm a bit late on this topic.  But IMO I'm not sure a modal dialog needing human intervention to proceed with rest of queue is good idea.  Seems it would prevent ability of unattended backup.  Isn't the "channel blocked" just a potential network connection issue?  

    I think the error notice could be displayed and logged in detail in the log.  But the queue and remaining scheduled backups should proceed.  Perhaps even including the one that originally failed on subsequent scheduled runs (ie. don't deactivate it).

    That way other profiles to different servers can run.  And potentially, if the network issues clear up, the original one that had the problem could proceed.

    I'd hate to come home after a few days away to find all rsync job had been suspended due to an issue (that could be temporary) with just one.

    Thanks!
    -Dan 
  • gchen
    Good point.  I'll add this to the to-do list.
  • Germo GörtzGermo Görtz
    would be fine to find a way not to stop the task after this 120 second error, but to continue the current task. I get this error nearly every time an have nearly no completed backups because of it.
  • gchen
    Are you stilling getting this error with the latest 1.4 build?
  • Germo GörtzGermo Görtz
    I used the 1.4 version from the download section and downloaded it 2 days ago.
  • Germo GörtzGermo Görtz
    DaVig wrote "I'd hate to come home after a few days away to find all rsync job had been suspended due to an issue (that could be temporary) with just one."

    You added this point to the to-do list. Is it still on the to do list?

    It would be fine to be only informed about this error, but to proceed with the next job in queue and maybe to try again and again if it is an "auto upload".

    I used the registry entry to set the TransmissionTimeout to 3600 seconds, but I still get this rsync channel blocking error. I will set to 7200 seconds. 

    BTW, when a sync job was not successfully finished, how I can see which backups are completed and which not?
    I have seen that after a successful backup of my C drive in "auto upload" mode a lot of old backups have been deleted, but not all. Maybe acrosync detected incomplete backups and deleted them? If this is the case - fine! On the other side that means, my aout upload of D driver never has been finished successfully, no old backups are deleted.
  • Germo GörtzGermo Görtz
    sorry, there is an option: "Don't stop this profile when a connection error occurs", I will use it.
  • gchen
    If you are using a timeout of 3600 seconds and still get the blocking error, then it is definitely blocked, which is likely caused by issues in the libssh2 library.

    There are two workarounds.  The first is to change to the rsync daemon mode (by disabling the 'via ssh' option).  This will bypass the ssh layer thus avoiding the libssh2 library.  The second is to switch to libssh, another ssh library, which is shipped with Acrosync for Windows version 1.5 but disabled by default.  You'll just need to modify the registry value 'UseLibssh' to 1 (if you do it correctly you'll see a log message saying 'the libssh dll has been loaded).
  • Germo GörtzGermo Görtz
    Hallo gchen,

    'via ssh' is always disabled in all my profiles, because the was an issue long time ago and I did not enable after this happend.

    Regarding the option "Don't stop profile when a connection error occurs":
    It doesn't work as I think it should. I used this option in all 4 profiles (C:, D:, c:, d:; the first two are 'upload' with Volume Shadow Copy, the last two are 'auto upload' which doesn't use Volume Shadow Copy).
    But when I had a look today in the morning on acrosync there was an error window open again and acrosync stopped.
    You see this happened at 01:59:43, at 10:02:20 I have seen the error window, pressed OK and only after this the next job started.
    I think this option should prevent this kind of error windows? 

    What I also see:
    the "Transmission timeout" is also used when trying to open local files. Here you can see that 2 hours acrosync tried to open 'd:/Log/Acrosync/acrosync_client.log'
    I think it would be better to have separate timeout parameters for rsynch channel and for trying to open local files.
    But on the other side, in the profile "C:" which uses Volume Shadow Copy there is no wait for the file to open.


    2016/01/02 20:13:33    Acrosync for windows 1.5 build 530 initialized
    2016/01/02 20:13:33    Transmission timeout set to 7200 seconds
    2016/01/02 22:33:14    Failed to open 'd:/Log/Acrosync/acrosync_client.log': Der Prozess kann nicht auf die Datei zugreifen, da sie von einem anderen Prozess verwendet wird.

    2016/01/02 22:33:14    Ignore 'Log/Acrosync/acrosync_client.log' due to open error
    2016/01/02 22:34:53    Uploaded Log/Acrosync/acrosync_client.log-2016-0102-20 (2007136/2007276)
    2016/01/03 00:00:00    Performing a full backup of C:/
    2016/01/03 01:00:00    Performing a full backup of D:/
    2016/01/03 01:59:43    The rsync channel has been blocked for more than 7200 seconds (read:0:0:29:1:1:1:0:128000:28158:128000:0:0:0:1)
    2016/01/03 02:00:00    Performing a full backup of c:/
    2016/01/03 03:00:00    Performing a full backup of d:/
    2016/01/03 10:02:20    Failed to open 'c:/hiberfil.sys': Der Prozess kann nicht auf die Datei zugreifen, da sie von einem anderen Prozess verwendet wird.

    2016/01/03 10:02:20    Ignore 'hiberfil.sys' due to open error
    2016/01/03 10:06:12    Uploaded Program Files (x86)/DVBLogic/DVBLink/dvblink_configuration.xml (3356/36)
    2016/01/03 10:06:12    Failed to open 'c:/Program Files (x86)/DVBLogic/DVBLink/dvblink_server.log': Der Prozess kann nicht auf die Datei zugreifen, da sie von einem anderen Prozess verwendet wird.

    2016/01/03 10:06:12    Ignore 'Program Files (x86)/DVBLogic/DVBLink/dvblink_server.log' due to open error
    2016/01/03 10:06:13    Failed to open 'c:/Program Files (x86)/DVBLogic/DVBLink/dvblink_webserver.log': Der Prozess kann nicht auf die Datei zugreifen, da sie von einem anderen Prozess verwendet wird.

    2016/01/03 10:06:13    Ignore 'Program Files (x86)/DVBLogic/DVBLink/dvblink_webserver.log' due to open error
    2016/01/03 10:06:23    Failed to open 'c:/Program Files (x86)/EaseUS/System GoBack Free/bin/easeus.log': Der Prozess kann nicht auf die Datei zugreifen, da sie von einem anderen Prozess verwendet wird.

    2016/01/03 10:06:23    Ignore 'Program Files (x86)/EaseUS/System GoBack Free/bin/easeus.log' due to open error
    2016/01/03 10:06:54    Uploaded Program Files (x86)/Google/CrashReports/13ff8852-1873-47bc-a021-eb370b4b7d5a.dmp (0/16)
    2016/01/03 10:06:54    Uploaded Program Files (x86)/Google/CrashReports/13ff8852-1873-47bc-a021-eb370b4b7d5a.txt (0/16)
    2016/01/03 10:07:01    Uploaded Program Files (x86)/Google/CrashReports/e80b08af-5e71-4bb2-8b34-8bc7712fd9be.dmp (0/16)
    2016/01/03 10:07:01    Uploaded Program Files (x86)/Google/CrashReports/e80b08af-5e71-4bb2-8b34-8bc7712fd9be.txt (0/16)
    2016/01/03 10:11:07    Uploaded Program Files (x86)/Notepad++/plugins/DSpellCheck.dll (1569280/1569392)
    2016/01/03 10:11:09    Uploaded Program Files (x86)/Notepad++/plugins/nppplugin_solutionhub.dll (289280/289316)
    2016/01/03 10:11:09    Uploaded Program Files (x86)/Notepad++/plugins/nppplugin_solutionhub_ui.dll (315904/315940)
    2016/01/03 10:11:09    Uploaded Program Files (x86)/Notepad++/plugins/nppplugin_svn.dll (74240/74264)
    2016/01/03 10:11:09    Uploaded Program Files (x86)/Notepad++/plugins/Config/nppplugin_tsvn.config (414/434)
    2016/01/03 10:11:09    Uploaded Program Files (x86)/Notepad++/plugins/doc/nppplugin_tsvn_help.txt (1181/1201)
    2016/01/03 10:12:35    Failed to open 'c:/Program Files (x86)/TeamViewer/TeamViewer10_Logfile.log': Der Prozess kann nicht auf die Datei zugreifen, da sie von einem anderen Prozess verwendet wird.

    2016/01/03 10:12:35    Ignore 'Program Files (x86)/TeamViewer/TeamViewer10_Logfile.log' due to open error
    2016/01/03 10:15:35    Uploaded Program Files/Microsoft SQL Server/110/Shared/ErrorDumps/SQLDmpr0209.mdmp (319842/319878)


    Germo
  • Germo GörtzGermo Görtz
    I see, the waiting time for open files has nothing to do with Voume Shadow Copy. Profile "c:" is an auto upload, and there is no waiting time.
    Maybe acrosync was not waiting 2 hours to open the file but was waiting fore something else 7200 seconds?
    But in this case it would be more usefull to write an additional entry into the log to know, acrosynch was waiting for something 7200 seconds. Otherwise the interpretation of the log could be wrong. 
  • Germo GörtzGermo Görtz
    and again, after 7200 seconds an error windows opened, and only after confirming and closing the window (12:34) the next stop started:

    2016/01/03 10:30:06    Ignore 'ProgramData/SAMSUNG/Samsung Link/db/media_p9nx2wjjem.mta' due to open error
    2016/01/03 12:30:07    The rsync channel has been blocked for more than 7200 seconds (read:0:0:21:1:1:1:0:128000:12:128000:0:0:0:1)
    2016/01/03 12:34:06    rsync command: rsync --server --modify-window=2 --sender --out-format=%n --links -tude. . NetBackup/AcerR7/C/

  • gchen
    Do you have verbose logging enabled?  If so, then it looks like the blocking was indeed caused by the failure to open 'media_p9nx2wjjem.mta'.

    You can use the Shadow Copy option to get rid of those open errors.



Sign In or Register to comment.