Back-in-time hangs on xdpyinfo #854

jasiomonitor · 2017-12-24T14:10:33Z

Hi,

After having configured back-in-time, I run it as a cron.daily automated routine.

Until quite recently it worked just fine, but a few days ago it suddenly stopped. I noticed that the daily backup had not been completed, and back-in-time waited for xdpyinfo process to exit, which did not actually happen. After I killed xdpyinfo manually, the backup resumed and completed without any further errors. On my machine the problem is fully replicable as long, as back-in-time is called from cron or a terminal console. However, when run from a terminal console window with the same privileges it executes successfully without any flaws. Xdpyinfo itself when run from the terminal console immediately returns with an exit code 1 and an error message saying 'unable to open display ""'. In the terminal window it lists some graphic-related information and exits with the exit code 0.

I use OpenSUSE Leap 42.3, kernel Linux version 4.4.103-36-default (after an upgrade, previously since October it was 4.4.92 ). Backintime is 1.1.20 as packaged by OpenSUSE mainteners, which was upgraded early December.

The issue may be related to an upgrade which was done the evening before the flaw occurred for the first time. The following packages were then updated:

kernel-default-4.4.103
kernel-default-devel-4.4.103
kernel-devel-4.4.103
kernel-macros-4.4.103
libGraphicsMagick3-config-1.3.25
libGraphicsMagick-Q16-3-1.3.25
libxcb1-1.11.1
libxcb1-32bit-1.11.1
libxcb-composite0-1.11.1
libxcb-damage0-1.11.1
libxcb-devel-1.11.1
libxcb-dpms0-1.11.1
libxcb-dri2-0-1.11.1
libxcb-dri2-0-32bit-1.11.1
libxcb-dri3-0-1.11.1
libxcb-dri3-0-32bit-1.11.1
libxcb-glx0-1.11.1
libxcb-glx0-32bit-1.11.1
libxcb-present0-1.11.1
libxcb-present0-32bit-1.11.1
libxcb-randr0-1.11.1
libxcb-randr0-32bit-1.11.1
libxcb-record0-1.11.1
libxcb-render0-1.11.1
libxcb-render0-32bit-1.11.1
libxcb-res0-1.11.1
libxcb-screensaver0-1.11.1
libxcb-shape0-1.11.1
libxcb-shape0-32bit-1.11.1
libxcb-shm0-1.11.1
libxcb-shm0-32bit-1.11.1
libxcb-sync1-1.11.1
libxcb-sync1-32bit-1.11.1
libxcb-xevie0-1.11.1
libxcb-xf86dri0-1.11.1
libxcb-xfixes0-1.11.1
libxcb-xfixes0-32bit-1.11.1
libxcb-xinerama0-1.11.1
libxcb-xinerama0-32bit-1.11.1
libxcb-xkb1-1.11.1
libxcb-xkb1-32bit-1.11.1
libxcb-xprint0-1.11.1
libxcb-xtest0-1.11.1
libxcb-xv0-1.11.1
libxcb-xvmc0-1.11.1
pam-1.3.0
pam-32bit-1.3.0

Google did not find any traces of a similar issue.

dro123 · 2018-01-07T11:51:34Z

Same here with openSUSE Tumbleweed

jim-moe · 2018-01-13T21:58:37Z

Opensuse 42.3
linux 4.4.103-36-default x86_64
BackInTime v1.1.20

I was also am experiencing this issue.
I have three instances of xdpyinfo since 3 jobs are started, one as root and two as user. The jobs hang on xdpyinfo and only proceed after killing each xdpyinfo. They cause the process Xorg to run a CPU at 98%.

Two other things to note:

I am receiving the following mail each time BIT starts. See the journal log below.
Cron sma-user3x@sma-server3 /usr/bin/nice -n19 /usr/bin/ionice -c2 -n7 /usr/bin/backintime --debug
WARNING: import keyring failed
WARNING: import keyring failed
WARNING: import keyring failed
Here is the first instance of BIT. Subsequent instances only log that they have started. All are apparently waiting for xdpyinfo to happen.
Jan 13 05:49:12 sma-server3 nmbd[2637]: This response was from IP 192.168.69.109, reporting an IP address of 192.168.69.109.
Jan 13 06:00:01 sma-server3 cron[24959]: pam_unix(crond:session): session opened for user root by (uid=0)
Jan 13 06:00:01 sma-server3 cron[24960]: pam_unix(crond:session): session opened for user sma-user3x by (uid=0)
Jan 13 06:00:01 sma-server3 systemd[1]: Started Session 1588 of user root.
Jan 13 06:00:01 sma-server3 systemd[1]: Started Session 1589 of user sma-user3x.
Jan 13 06:00:01 sma-server3 CRON[24963]: (sma-user3x) CMD (/usr/bin/nice -n19 /usr/bin/ionice -c2 -n7 /usr/bin/backintime --debug --profile-id 2 backup-job >/dev/null)
Jan 13 06:00:01 sma-server3 CRON[24959]: pam_unix(crond:session): session closed for user root
Jan 13 06:00:04 sma-server3 /backintime.py[25001]: WARNING: import keyring failed
Jan 13 06:00:04 sma-server3 python3[25001]: backintime (sma-user3x/1): DEBUG: [common/backintime.py:518 arg_parse] Arguments: {'debug': True, 'command': 'backup-job', 'profile_id': 2, 'func': <function backupJob at 0x7f7700b59d90>} | unknownArgs: []
Jan 13 06:00:04 sma-server3 python3[25001]: backintime (sma-user3x/1): DEBUG: [common/tools.py:1323 BackupJobDaemon.daemonize] first fork pid: 25076
Jan 13 06:00:04 sma-server3 python3[25076]: backintime (sma-user3x/1): DEBUG: [common/tools.py:1323 BackupJobDaemon.daemonize] first fork pid: 0
Jan 13 06:00:04 sma-server3 python3[25076]: backintime (sma-user3x/1): DEBUG: [common/tools.py:1332 BackupJobDaemon.daemonize] decouple from parent environment
Jan 13 06:00:04 sma-server3 python3[25076]: backintime (sma-user3x/1): DEBUG: [common/tools.py:1340 BackupJobDaemon.daemonize] second fork pid: 25078
Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/1): DEBUG: [common/tools.py:1340 BackupJobDaemon.daemonize] second fork pid: 0
Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/1): DEBUG: [common/tools.py:1349 BackupJobDaemon.daemonize] redirect standard file descriptors
Jan 13 06:00:04 sma-server3 dbus[1339]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.3418" (uid=1000 pid=25078 comm="python3 -Es /usr/share/backintime/common/backintim") interface="org.freedesktop.DBus.Introspectable" member="Introspect" error name="(unset)" requested_reply="0" destination=":1.168" (uid=0 pid=27617 comm="/usr/bin/python3 -Es /usr/share/backintime/qt4/ser")
Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/1): DEBUG: [common/backintime.py:585 getConfig] config file: /home/sma-user3x/.config/backintime/config
Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/1): DEBUG: [common/backintime.py:586 getConfig] profiles: ['1', '2']
Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/1): DEBUG: [common/configfile.py:476 Config.set_current_profile] change current profile: 2
Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/2): DEBUG: [common/pluginmanager.py:88 PluginManager.load_plugins] Register plugin path /usr/share/backintime/plugins
Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/2): DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin notifyplugin.py

Jan 13 06:00:04 sma-server3 CRON[24960]: pam_unix(crond:session): session closed for user sma-user3x

....[ Here is the message I received as noted above ]....

Jan 13 06:00:05 sma-server3 postfix/pickup[23584]: 227472563E7: uid=1000 from=
Jan 13 06:00:05 sma-server3 postfix/cleanup[25085]: 227472563E7: message-id=[email protected]
Jan 13 06:00:05 sma-server3 postfix/qmgr[32044]: 227472563E7: from=[email protected], size=937, nrcpt=2 (queue active)
Jan 13 06:00:05 sma-server3 postfix/local[25088]: 227472563E7: to=[email protected], orig_to=, relay=local, delay=0.5, delays=0.36/0.13/0/0, dsn=2.0.0, status=sent (delivered to maildir)
Jan 13 06:00:06 sma-server3 postfix/smtp[25089]: 227472563E7: to=[email protected], relay=mail.sma.com[192.168.69.246]:25, delay=1.3, delays=0.36/0.43/0.22/0.3, dsn=2.0.0, status=sent (250 6648841 message accepted for delivery)
Jan 13 06:00:06 sma-server3 postfix/qmgr[32044]: 227472563E7: removed

....[ Here is the second instance starting ]....
Jan 13 07:00:01 sma-server3 cron[26488]: pam_unix(crond:session): session opened for user root by (uid=0)
Jan 13 07:00:01 sma-server3 cron[26489]: pam_unix(crond:session): session opened for user sma-user3x by (uid=0)
Jan 13 07:00:01 sma-server3 systemd[1]: Started Session 1593 of user root.
Jan 13 07:00:01 sma-server3 systemd[1]: Started Session 1594 of user sma-user3x.
Jan 13 07:00:01 sma-server3 CRON[26492]: (sma-user3x) CMD (/usr/bin/nice -n19 /usr/bin/ionice -c2 -n7 /usr/bin/backintime backup-job >/dev/null 2>&1)
Jan 13 07:00:02 sma-server3 CRON[26488]: pam_unix(crond:session): session closed for user root
Jan 13 07:00:02 sma-server3 dbus[1339]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.3429" (uid=1000 pid=26532 comm="python3 -Es /usr/share/backintime/common/backintim") interface="org.freedesktop.DBus.Introspectable" member="Introspect" error name="(unset)" requested_reply="0" destination=":1.168" (uid=0 pid=27617 comm="/usr/bin/python3 -Es /usr/share/backintime/qt4/ser")
Jan 13 07:00:02 sma-server3 CRON[26489]: pam_unix(crond:session): session closed for user sma-user3x

....[ At 11:06 I killed the xdpyinfo apps ]....
Jan 13 11:06:26 sma-server3 python3[25078]: backintime (sma-user3x/2): DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin userscriptsplugin.py
....more python3...
Jan 13 11:06:37 sma-server3 python3[25078]: backintime (sma-user3x/2): DEBUG: [common/snapshots.py:1357 Snapshots._take_snapshot] Call command "rsync -rtDHh --links ...

Jan 13 11:06:45 sma-server3 python3[26532]: backintime (sma-user3x/1): INFO: Create hard-links
Jan 13 11:06:47 sma-server3 python3[26532]: backintime (sma-user3x/1): INFO: Call rsync to take the snapshot
....more python3....

And so on normally until the end:
Jan 13 11:07:48 sma-server3 dbus[1339]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.3466" (uid=1000 pid=652 comm="python3 -Es /usr/share/backintime/common/backintim") interface="org.freedesktop.DBus.Introspectable" member="Introspect" error name="(unset)" requested_reply="0" destination=":1.168" (uid=0 pid=27617 comm="/usr/bin/python3 -Es /usr/share/backintime/qt4/ser")

jim-moe · 2018-01-15T21:04:57Z

I have gotten 2 of 3 backups working again. I de-installed xdpyinfo; it is apparently not very important.

The 2 working backups are in user space. The non-working backup is in root space; it just hangs waiting for something, I know not what.

----[ Here is the output from a hung session ]----
Back In Time
Version: 1.1.20
DEBUG: [common/backintime.py:585 getConfig] config file: /root/.config/backintime/config
DEBUG: [common/backintime.py:586 getConfig] profiles: ['1']
DEBUG: [common/pluginmanager.py:88 PluginManager.load_plugins] Register plugin path /usr/share/backintime/plugins
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin notifyplugin.py
root:/etc/postfix> DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin userscriptsplugin.py
DEBUG: [common/snapshots.py:953 Snapshots.has_old_snapshots] Found old snapshots: False
DEBUG: [common/applicationinstance.py:88 ApplicationInstance.check] No process with PID 27254
DEBUG: [common/applicationinstance.py:73 ApplicationInstance.check] No PID file
INFO: [common/snapshots.py:991 Snapshots.take_snapshot] Lock
----[ end ]----

Is there any way to get more info on what BIT is (not) doing?

buhtz · 2022-09-25T08:09:47Z

@jasiomonitor and @jim-moe There is a new forming maintaining team and we do review all issues. Is this problem still relevant for you or did you find a solution?

Tag: Feedback, external tools (xdpinfo), Enhancement

I suggest to keep it open and take a closer look about how and why BIT calls xdpinfo. I also assume it can be replaced by a python package.

jasiomonitor · 2022-10-11T08:07:09Z

Hi, Thank you for the info. Currently I'm on a vacation leave, with no access to my resources, so I really can't tell. I even do not remember what the problem was about, and if I found any fix or solution. I'll be able to return to it in a month's time. Best regards. Jan. niedz., 25 wrz 2022, 10:09 użytkownik buhtzz ***@***.***> napisał:

…

@jasiomonitor <https://github.com/jasiomonitor> and @jim-moe <https://github.com/jim-moe> There is a new forming maintaining team and we do review all issues. Is this problem still relevant for you or did you find a solution? Tag: Feedback, external tools (xdpinfo), Enhancement I suggest to keep it open and take a closer look about how and why BIT calls xdpinfo. I also assume it can be replaced by a python package. — Reply to this email directly, view it on GitHub <#854 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AFA5ENCXTXBLKLJX74GIJK3WAACFNANCNFSM4EJPXT6Q> . You are receiving this because you were mentioned.Message ID: ***@***.***>

buhtz · 2023-06-29T07:42:40Z

Dear @jasiomonitor and @jim-moe,
do you have some updates in this case?

Please try to reproduce the problem with the latest BIT 1.3.3.

buhtz · 2023-08-01T11:08:11Z

I need to close the issue in the near future if no new information is added to it.

jasiomonitor · 2023-08-01T16:11:38Z

Hi, Thank you for your patience. At the moment I'm to far away from the computer on which the original issue was observed, to tell if I can reproduce it on the newer version. I expect to be able to do it in the other half of August. Best regards Jan. wt., 1 sie 2023, 14:08 użytkownik buhtz ***@***.***> napisał:

…

I need to close the issue in the near future if no new information is added to it. — Reply to this email directly, view it on GitHub <#854 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AFA5ENCQWF6TGOOFT4K3VM3XTDPSNANCNFSM4EJPXT6Q> . You are receiving this because you were mentioned.Message ID: ***@***.***>

aryoda · 2023-08-01T19:48:46Z

It looks like this problem was caused by the system tray plugin (formerly known as notifyplugin.py):

Jan 13 06:00:04 sma-server3 python3[25078]: backintime (sma-user3x/2): DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin notifyplugin.py

This GUI plugin was even called when BiT CLI was started via a CRON job and spawned an xdpyinfo process (checkXServer()) to find out if a system tray icon can be shown.

Since my fix of #1306 on July 17, 2023, xdpyinfo is no longer used here and shall therefore not cause this problem anymore.

This old function is still in use for other BiT functionality:

passwordFromUser()

backintime/common/password.py

Lines 231 to 247 in cee422e

    
               def passwordFromUser(self, parent, profile_id = None, mode = None, pw_id = 1, prompt = None): 
        
                   """ 
        
                   ask user for password. This does even work when run as cronjob 
        
                   and user is logged in. 
        
                   """ 
        
                   if prompt is None: 
        
                       """ 
        
                       Profile {name}: Enter password for {mode} 
        
                       """ 
        
                       prompt = _("Profile '{profile}': Enter password for {mode}: ") \ 
        
                           .format( 
        
                               profile=self.config.profileName(profile_id), 
        
                               mode=self.config.SNAPSHOT_MODES[mode][pw_id+1]) 
        
                   tools.registerBackintimePath('qt') 
        
                   x_server = tools.checkXServer()

unlockSshAgent():

backintime/common/sshtools.py

Line 351 in cee422e

if not password_available and not tools.checkXServer():

New diagnostics functionality for Qt5 (@buhtz which could use my new function is_Qt5_working() now instead):

backintime/common/diagnostics.py

Lines 189 to 204 in cee422e

    
           def _get_qt_information(): 
        
               """Collect Version and Theme information from Qt. 
        
               If environment variable DISPLAY is set a temporary QApplication instances 
        
               is created. 
        
               """ 
        
               try: 
        
                   import PyQt5.QtCore 
        
                   import PyQt5.QtGui 
        
                   import PyQt5.QtWidgets 
        
               except ImportError: 
        
                   return '(Cannot import PyQt5)' 
        
               # Themes 
        
               theme_info = {} 
        
               if tools.checkXServer():  # TODO use tools.is_Qt5_working() when stable

So I think we can close this issue (after a grace period of a few weeks) unless @jasiomonitor and @jim-moe report otherwise here.

buhtz · 2023-09-26T17:58:19Z

Feel free to re-open if you have new information.

aryoda · 2023-12-22T08:41:01Z

Problem reoccurred with new code on openSuse too. See #1580 and #1592. Continue to pursue the issue there...

emtiu added Bug External depends on others/upstream labels Oct 11, 2022

buhtz added the Feedback needs user response, may be closed after timeout without a response label Mar 19, 2023

buhtz added this to the 1.3.5 / 1.4.0 milestone Mar 19, 2023

buhtz modified the milestones: 3rd release from now, 2nd release from now Aug 23, 2023

buhtz removed the Feedback needs user response, may be closed after timeout without a response label Sep 26, 2023

buhtz closed this as completed Sep 26, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Back-in-time hangs on xdpyinfo #854

Back-in-time hangs on xdpyinfo #854

jasiomonitor commented Dec 24, 2017 •

edited

Loading

dro123 commented Jan 7, 2018

jim-moe commented Jan 13, 2018

jim-moe commented Jan 15, 2018

buhtz commented Sep 25, 2022

jasiomonitor commented Oct 11, 2022 via email

buhtz commented Jun 29, 2023

buhtz commented Aug 1, 2023

jasiomonitor commented Aug 1, 2023 via email

aryoda commented Aug 1, 2023

buhtz commented Sep 26, 2023

aryoda commented Dec 22, 2023

Back-in-time hangs on xdpyinfo #854

Back-in-time hangs on xdpyinfo #854

Comments

jasiomonitor commented Dec 24, 2017 • edited Loading

dro123 commented Jan 7, 2018

jim-moe commented Jan 13, 2018

jim-moe commented Jan 15, 2018

buhtz commented Sep 25, 2022

jasiomonitor commented Oct 11, 2022 via email

buhtz commented Jun 29, 2023

buhtz commented Aug 1, 2023

jasiomonitor commented Aug 1, 2023 via email

aryoda commented Aug 1, 2023

buhtz commented Sep 26, 2023

aryoda commented Dec 22, 2023

jasiomonitor commented Dec 24, 2017 •

edited

Loading