user-callback not called until after remote server ping fail is acknowledged

[kortschak]

I have written a user-callback that does a variety of things for my remote backup target. It checks the confirms the callback is for the remote target and the reason is to mount necessary drived, checks the WiFi ESSID for location, and then sends a WOL packet to the server (a NAS, it spends most of its time off) and waits for a successful GET on the server's admin page (latency of about 1 minute).

This should just work when the user selects the remote profile to view snapshots, but it turns out that the call back is not called until the user acknowledges that the remote server is not responding to pings. It seems to me that either the ping should happen after the call to the user-callback with the remote profile and reason 7, or there should be another reason that deals with requesting that the server be up.

[kortschak]

It looks like this is fixed by 219e7f2, though that looks like a fairly blunt approach for the problem here where it would still be nice to do the necessary checks, but only after the server has been woken.

[Germar]

Sorry, but I can't confirm this. user-callback is called with event 7 (mount drives) before the ping check is done. Maybe your user-callback need to wait until your remote system is up and running!?

Actually the ping check is no ping (ICMP) but a port check on the configured ssh port. So your user-callback should check if it could login to the remote host with ssh before it does exit. BiT will wait until the script finished.

Take a look at #648

[kortschak]

@Germar Which version did you attempt to reproduce this on? I am using 1.1.12 (as part of ubuntu 16.04). It may well be fixed at master, but #648 is not the fix - I'm not asking for a shutdown, the server handles that by period of inactivity.

The user-callback I use is built to get the system up and running, so there would be a deadlock if it had to wait for the server to be up. The code is here, but conceptually, it sends a WOL packet, then waits until the server is up (or times out) and returns.

The issue here is that the script is not invoked until I click the acknowledgment dialogue - this is clearly apparent from watching log in verbose logging mode - no log line corresponding to an invocation appears until after BiT returns complaining about the "ping" failure.

[kortschak]

The other data point on this is that the issue only present when attempting to change to the remote profile in the GUI for navigating snapshots - there is no problem with BiT waking the server and performing the back up which works as expected.

[kortschak]

I have narrowed it down to the remount call in app.py with judicious Qt notifications (the code at master is substantively the same here), but delving into mount.py where I'd actually be able to see what's going on doesn't allow that.

[kortschak]

If the following diff is applied to 1.1.12 and you have a server that is down using a waiting wake-on-lan similar to my user-callback you will get the output that follows.

diff --git a/common/plugins/usercallbackplugin.py b/common/plugins/usercallbackplugin.py
index 402f49d..05fed37 100644
--- a/common/plugins/usercallbackplugin.py
+++ b/common/plugins/usercallbackplugin.py
@@ -83,6 +83,7 @@ class UserCallbackPlugin( pluginmanager.Plugin ):
         self.notify_callback('6')

     def do_mount(self):
+        print("callback")
         self.notify_callback('7')

     def do_unmount(self):
diff --git a/common/sshtools.py b/common/sshtools.py
index 46fd44e..2f9be58 100644
--- a/common/sshtools.py
+++ b/common/sshtools.py
@@ -371,9 +371,11 @@ class SSH(mount.MountControl):

     def check_ping_host(self):
         """connect to remote port and check if it is open"""
+        print("check ping host")
         logger.debug('Check ping host', self)
         count = 0
         while count < 5:
+            print("try")
             try:
                 with socket.create_connection((self.host, self.port), 2.0) as s:
                     result = s.connect_ex(s.getpeername())
@@ -386,6 +388,7 @@ class SSH(mount.MountControl):
             count += 1
             sleep(0.2)
         if result != 0:
+            print("failed to ping host")
             logger.debug('Failed pinging host %s' %self.host, self)
             raise MountException( _('Ping %s failed. Host is down or wrong address.') % self.host)

$ backintime-qt4 

Back In Time
Version: 1.1.12

Back In Time comes with ABSOLUTELY NO WARRANTY.
This is free software, and you are welcome to redistribute it
under certain conditions; type `backintime --license' for details.

callback
check ping host
try
try
try
try
try
failed to ping host

<dismiss dialogue resulting from the MountException call>

callback

This clearly demonstrates that the callback is made after the "ping" checks. (Note that the initially callback output is from the default profile which is a local disk).

The stack trace for check_ping_host's call shows the problem. There are calls to mount, that do not invoke the user-callback:

  File "/usr/share/backintime/qt4/app.py", line 1518, in <module>
    qapp.exec_()
  File "/usr/share/backintime/qt4/app.py", line 558, in on_profile_changed
    self.remount(profile_id, old_profile_id)
  File "/usr/share/backintime/qt4/app.py", line 585, in remount
    hash_id = mnt.remount(new_profile_id)
  File "/usr/share/backintime/common/mount.py", line 150, in remount
    return self.mount(mode = mode, plugins = False, **kwargs)
  File "/usr/share/backintime/common/mount.py", line 86, in mount
    return tools.mount(check = check)
  File "/usr/share/backintime/common/mount.py", line 208, in mount
    self.pre_mount_check()
  File "/usr/share/backintime/common/sshtools.py", line 143, in pre_mount_check
    self.check_ping_host()
  File "/usr/share/backintime/common/sshtools.py", line 375, in check_ping_host
    traceback.print_stack()

The path that does lead to a user-callback happens a few lines latter in app.py at 561:

  File "/usr/share/backintime/qt4/app.py", line 1518, in <module>
    qapp.exec_()
  File "/usr/share/backintime/qt4/app.py", line 561, in on_profile_changed
    self.config.PLUGIN_MANAGER.do_mount()
  File "/usr/share/backintime/common/pluginmanager.py", line 173, in do_mount
    plugin.do_mount()
  File "/usr/share/backintime/plugins/usercallbackplugin.py", line 87, in do_mount
    traceback.print_stack()

[Germar]

Ah, okay. I missed that it wasn't working only for remount.

So this is caused by af024a5

Will have a look on how I can fix it.

[kortschak]

Thanks.