Hide Forgot
Description of problem: engine-backup --mode=restore blows up with an obscure error when following Procedure 3.1 documented in the RHV4.0 Upgrade Guide. Version-Release number of selected component (if applicable): Source RHEV 3.6.9, destination, 4.0.3 How reproducible: At will Steps to Reproduce: 1. Build a RHEL 7.1 system from ISO. yum update it to 7.2.latest. I have a hunch this is key. Install RHV 4 on it. 2. engine-backup from my RHEV 3.6 system as documented in steps 1-2 of Procedure 3.1 on the RHV4 Upgrade Guide. 3. engine-backup --mode=restore on the RHV 4.0 system as documented in step 5 of Procedure 3.1 on the RHV4 Upgrade Guide. Actual results: engine-backup --mode-restore blows up with an obscure error. Expected results: engine-backup --mode=restore should run to completion. Additional info: First, do the engine-backup on the old RHEVM and copy the bck file to the destination. [root@rhevm2014 gregs]# engine-backup --scope=all --mode=backup --file=backup.bck --log=backuplog.log Backing up: Notifying engine - Files - Engine database 'engine' - DWH database 'ovirt_engine_history' - Reports database 'ovirt_engine_reports' Packing into file 'backup.bck' Notifying engine Done. [root@rhevm2014 gregs]# scp backup.bck root.10.108:/home/gregs/ root.10.108's password: backup.bck 100% 13MB 13.1MB/s 00:01 [root@rhevm2014 gregs]# Now on the destination system, do the restore. This blows up with an ugly error. [root@rhevm2017 gregs]# engine-backup --mode=restore --file=backup.bck --log=restore20161016c.log --provision-db --provision-dwh-db --restore-permissions Preparing to restore: - Unpacking file 'backup.bck' ------------------------------------------------------------------------------ Please note: A Reports dump was found inside the backup. This version does not support Reports, and the dump and configuration files will not be restored. ------------------------------------------------------------------------------ Restoring: - Files ------------------------------------------------------------------------------ Please note: Operating system is different from the one used during backup. Current operating system: redhat7 Operating system at backup: redhat6 Apache httpd configuration will not be restored. You will be asked about it on the next engine-setup run. ------------------------------------------------------------------------------ Provisioning PostgreSQL users/databases: - user 'engine', database 'engine' FATAL: Provisioning database 'engine' failed, please check the log for details [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# And here is the log file. [root@rhevm2017 gregs]# more restore20161016c.log 2016-10-17 00:20:34 24090: Start of engine-backup mode restore scope all file backup.bck 2016-10-17 00:20:34 24090: OUTPUT: Preparing to restore: 2016-10-17 00:20:34 24090: OUTPUT: - Unpacking file 'backup.bck' 2016-10-17 00:20:34 24090: Opening tarball backup.bck to /tmp/engine-backup.lB2UYupr0x 2016-10-17 00:20:34 24090: Verifying md5 2016-10-17 00:20:34 24090: Verifying version 2016-10-17 00:20:34 24090: Reading config 2016-10-17 00:20:34 24090: Reports dump found, notifying user that it is not restored 2016-10-17 00:20:34 24090: OUTPUT: Restoring: 2016-10-17 00:20:34 24090: OUTPUT: - Files 2016-10-17 00:20:34 24090: Restoring files 2016-10-17 00:20:35 24090: Reloading configuration 2016-10-17 00:20:35 24090: OUTPUT: Provisioning PostgreSQL users/databases: 2016-10-17 00:20:35 24090: provisionDB: user engine host localhost port 5432 database engi ne secured False secured_host_validation False 2016-10-17 00:20:35 24090: OUTPUT: - user 'engine', database 'engine' Current date and time Mon Oct 17 00:20:35 2016 ***L:ERROR Internal error: datetime initialization failed 2016-10-17 00:20:35 24090: FATAL: Provisioning database 'engine' failed, please check the log for details [root@rhevm2017 gregs]# Troubleshooting, we tried this experiment: [root@rhevm2017 gregs]# python -c 'import psycopg2' Current date and time Mon Oct 17 00:48:23 2016 Traceback (most recent call last): File "<string>", line 1, in <module> File "/usr/lib64/python2.7/site-packages/psycopg2/__init__.py", line 50, in <module> from psycopg2._psycopg import BINARY, NUMBER, STRING, DATETIME, ROWID ImportError: datetime initialization failed [root@rhevm2017 gregs]# The last several lines of an strace look like this: mmap(0x7f0ce2bec000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 10, 0x9000) = 0x7f0ce2bec000 close(10) = 0 mprotect(0x7f0ce2bec000, 4096, PROT_READ) = 0 close(9) = 0 stat("_heapq", 0x7ffeffe993d0) = -1 ENOENT (No such file or directory) open("_heapq.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("_heapqmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("_heapq.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("_heapq.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib64/python2.7/_heapq", 0x7ffeffe993d0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/_heapq.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/_heapqmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/_heapq.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/_heapq.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib64/python2.7/plat-linux2/_heapq", 0x7ffeffe993d0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/_heapq.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/_heapqmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/_heapq.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/_heapq.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib64/python2.7/lib-dynload/_heapq", 0x7ffeffe993d0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/lib-dynload/_heapq.so", O_RDONLY) = 9 fstat(9, {st_mode=S_IFREG|0755, st_size=22856, ...}) = 0 open("/usr/lib64/python2.7/lib-dynload/_heapq.so", O_RDONLY|O_CLOEXEC) = 10 read(10, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\16\0\0\0\0\0\0"..., 832) = 832 fstat(10, {st_mode=S_IFREG|0755, st_size=22856, ...}) = 0 mmap(NULL, 2117040, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 10, 0) = 0x7f0ce27de000 mprotect(0x7f0ce27e1000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce29e0000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 10, 0x2000) = 0x7f0ce29e0000 close(10) = 0 mprotect(0x7f0ce29e0000, 4096, PROT_READ) = 0 close(9) = 0 close(7) = 0 close(6) = 0 close(5) = 0 stat("/usr/lib64/python2.7/logging/atexit", 0x7ffeffe9a420) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/logging/atexit.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/logging/atexitmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/logging/atexit.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/logging/atexit.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("atexit", 0x7ffeffe9a420) = -1 ENOENT (No such file or directory) open("atexit.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("atexitmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("atexit.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("atexit.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib64/python2.7/atexit", 0x7ffeffe9a420) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/atexit.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/atexitmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/atexit.py", O_RDONLY) = 5 fstat(5, {st_mode=S_IFREG|0644, st_size=1705, ...}) = 0 open("/usr/lib64/python2.7/atexit.pyc", O_RDONLY) = 6 fstat(6, {st_mode=S_IFREG|0644, st_size=2203, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0cf004f000 read(6, "\3\363\r\n\317B\304Wc\0\0\0\0\0\0\0\0\4\0\0\0@\0\0\0s\300\0\0\0d\0"..., 4096) = 2203 fstat(6, {st_mode=S_IFREG|0644, st_size=2203, ...}) = 0 read(6, "", 4096) = 0 close(6) = 0 munmap(0x7f0cf004f000, 4096) = 0 close(5) = 0 close(4) = 0 stat("/usr/lib64/python2.7/site-packages/systemd/syslog", 0x7ffeffe9a9e0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/systemd/syslog.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/systemd/syslogmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/systemd/syslog.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/systemd/syslog.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("syslog", 0x7ffeffe9a9e0) = -1 ENOENT (No such file or directory) open("syslog.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("syslogmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("syslog.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("syslog.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib64/python2.7/syslog", 0x7ffeffe9a9e0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/syslog.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/syslogmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/syslog.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/syslog.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib64/python2.7/plat-linux2/syslog", 0x7ffeffe9a9e0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/syslog.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/syslogmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/syslog.py", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/syslog.pyc", O_RDONLY) = -1 ENOENT (No such file or directory) stat("/usr/lib64/python2.7/lib-dynload/syslog", 0x7ffeffe9a9e0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/lib-dynload/syslog.so", O_RDONLY) = 4 fstat(4, {st_mode=S_IFREG|0755, st_size=11600, ...}) = 0 open("/usr/lib64/python2.7/lib-dynload/syslog.so", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\r\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=11600, ...}) = 0 mmap(NULL, 2105848, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce25db000 mprotect(0x7f0ce25dd000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce27dc000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x1000) = 0x7f0ce27dc000 close(5) = 0 mprotect(0x7f0ce27dc000, 4096, PROT_READ) = 0 close(4) = 0 stat("/usr/lib64/python2.7/site-packages/systemd/_journal", 0x7ffeffe9a9e0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/systemd/_journal.so", O_RDONLY) = 4 fstat(4, {st_mode=S_IFREG|0755, st_size=11752, ...}) = 0 open("/usr/lib64/python2.7/site-packages/systemd/_journal.so", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=11752, ...}) = 0 mmap(NULL, 12609, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0cf004c000 mmap(0x7f0cf004e000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x1000) = 0x7f0cf004e000 close(5) = 0 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 5 fstat(5, {st_mode=S_IFREG|0644, st_size=40495, ...}) = 0 mmap(NULL, 40495, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7f0cefe81000 close(5) = 0 open("/lib64/libsystemd.so.0", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=162560, ...}) = 0 mmap(NULL, 162596, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0cefe59000 mmap(0x7f0cefe7f000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x25000) = 0x7f0cefe7f000 close(5) = 0 open("/lib64/libcap.so.2", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \26\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=20024, ...}) = 0 mmap(NULL, 2114112, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce23d6000 mprotect(0x7f0ce23da000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce25d9000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x3000) = 0x7f0ce25d9000 close(5) = 0 open("/lib64/libgcrypt.so.11", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0u\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=534488, ...}) = 0 mmap(NULL, 2621456, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce2155000 mprotect(0x7f0ce21d1000, 2097152, PROT_NONE) = 0 mmap(0x7f0ce23d1000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x7c000) = 0x7f0ce23d1000 mmap(0x7f0ce23d5000, 16, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f0ce23d5000 close(5) = 0 open("/lib64/libgpg-error.so.0", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000\n\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=19384, ...}) = 0 mmap(NULL, 2113656, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce1f50000 mprotect(0x7f0ce1f54000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce2153000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x3000) = 0x7f0ce2153000 close(5) = 0 open("/lib64/libdw.so.1", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200\227\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=297464, ...}) = 0 mmap(NULL, 2386184, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce1d09000 mprotect(0x7f0ce1d4e000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce1f4d000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x44000) = 0x7f0ce1f4d000 close(5) = 0 open("/lib64/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360*\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=88720, ...}) = 0 mmap(NULL, 2184192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce1af3000 mprotect(0x7f0ce1b08000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce1d07000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x14000) = 0x7f0ce1d07000 close(5) = 0 open("/lib64/libattr.so.1", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\23\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=19888, ...}) = 0 mmap(NULL, 2113904, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce18ee000 mprotect(0x7f0ce18f2000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce1af1000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x3000) = 0x7f0ce1af1000 close(5) = 0 open("/usr/lib64/elfutils/tls/x86_64/libelf.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) stat("/usr/lib64/elfutils/tls/x86_64", 0x7ffeffe9a860) = -1 ENOENT (No such file or directory) open("/usr/lib64/elfutils/tls/libelf.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) stat("/usr/lib64/elfutils/tls", 0x7ffeffe9a860) = -1 ENOENT (No such file or directory) open("/usr/lib64/elfutils/x86_64/libelf.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) stat("/usr/lib64/elfutils/x86_64", 0x7ffeffe9a860) = -1 ENOENT (No such file or directory) open("/usr/lib64/elfutils/libelf.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) stat("/usr/lib64/elfutils", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 open("/lib64/libelf.so.1", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0p+\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=91496, ...}) = 0 mmap(NULL, 2183520, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce16d8000 mprotect(0x7f0ce16ed000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce18ec000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x14000) = 0x7f0ce18ec000 close(5) = 0 open("/usr/lib64/elfutils/libbz2.so.1", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) open("/lib64/libbz2.so.1", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\27\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=68192, ...}) = 0 mmap(NULL, 2162024, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce14c8000 mprotect(0x7f0ce14d7000, 2093056, PROT_NONE) = 0 mmap(0x7f0ce16d6000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0xe000) = 0x7f0ce16d6000 close(5) = 0 mprotect(0x7f0ce16d6000, 4096, PROT_READ) = 0 mprotect(0x7f0ce18ec000, 4096, PROT_READ) = 0 mprotect(0x7f0ce1af1000, 4096, PROT_READ) = 0 mprotect(0x7f0ce1d07000, 4096, PROT_READ) = 0 stat("/etc/sysconfig/64bit_strstr_via_64bit_strstr_sse2_unaligned", 0x7ffeffe9b2a0) = -1 ENOENT (No such file or directory) mprotect(0x7f0ce1f4d000, 8192, PROT_READ) = 0 mprotect(0x7f0ce2153000, 4096, PROT_READ) = 0 mprotect(0x7f0ce23d1000, 4096, PROT_READ) = 0 mprotect(0x7f0ce25d9000, 4096, PROT_READ) = 0 mprotect(0x7f0cefe7f000, 4096, PROT_READ) = 0 mprotect(0x7f0cf004e000, 4096, PROT_READ) = 0 access("/etc/system-fips", F_OK) = -1 ENOENT (No such file or directory) munmap(0x7f0cefe81000, 40495) = 0 close(4) = 0 stat("/usr/lib64/python2.7/site-packages/systemd/_reader", 0x7ffeffe9a9e0) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/systemd/_reader.so", O_RDONLY) = 4 fstat(4, {st_mode=S_IFREG|0755, st_size=50272, ...}) = 0 open("/usr/lib64/python2.7/site-packages/systemd/_reader.so", O_RDONLY|O_CLOEXEC) = 5 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 832) = 832 fstat(5, {st_mode=S_IFREG|0755, st_size=50272, ...}) = 0 mmap(NULL, 52584, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f0ce14bb000 mprotect(0x7f0ce14c3000, 4096, PROT_NONE) = 0 mmap(0x7f0ce14c4000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x8000) = 0x7f0ce14c4000 close(5) = 0 mprotect(0x7f0ce14c4000, 4096, PROT_READ) = 0 close(4) = 0 close(3) = 0 write(2, "Traceback (most recent call last"..., 35Traceback (most recent call last): ) = 35 write(2, " File \"<string>\", line 1, in <m"..., 39 File "<string>", line 1, in <module> ) = 39 open("<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python27.zip/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/plat-linux2/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/lib-tk/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/lib-old/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/lib-dynload/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/python2.7/site-packages/gtk-2.0/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib/python2.7/site-packages/<string>", O_RDONLY) = -1 ENOENT (No such file or directory) write(2, " File \"/usr/lib64/python2.7/sit"..., 87 File "/usr/lib64/python2.7/site-packages/psycopg2/__init__.py", line 50, in <module> ) = 87 open("/usr/lib64/python2.7/site-packages/psycopg2/__init__.py", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=5838, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0cf004b000 read(3, "\"\"\"A Python driver for PostgreSQ"..., 4096) = 4096 write(2, " ", 4 ) = 4 write(2, "from psycopg2._psycopg import BI"..., 70from psycopg2._psycopg import BINARY, NUMBER, STRING, DATETIME, ROWID ) = 70 close(3) = 0 munmap(0x7f0cf004b000, 4096) = 0 write(2, "ImportError", 11ImportError) = 11 write(2, ": ", 2: ) = 2 write(2, "datetime initialization failed", 30datetime initialization failed) = 30 write(2, "\n", 1 ) = 1 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f0cef85e100}, {0x7f0cefb7c6a0, [], SA_RESTORER, 0x7f0cef85e100}, 8) = 0 close(8) = 0 exit_group(1) = ? +++ exited with 1 +++ [root@rhevm2017 gregs]# [root@rhevm2017 gregs]#
On that system, for same reasons, import psycopg2 from any python module fails and so our utility. Not really reproducible.
In the other bz, Pavel asked me to try python -c 'import datetime'. That led to behavior I don't understand but might be a huge clue. I log onto my new RHV server as root, but I put the .bck file and logs in /home/gregs. I don't get what's going on here. Why does it behave differently when I cd to root vs. when I'm sitting in /home/gregs while logged in as root? [root@rhevm2017 gregs]# python -c 'import datetime' Current date and time Mon Oct 17 08:58:39 2016 [root@rhevm2017 gregs]# python -c 'import psycopg2' Current date and time Mon Oct 17 08:58:44 2016 Traceback (most recent call last): File "<string>", line 1, in <module> File "/usr/lib64/python2.7/site-packages/psycopg2/__init__.py", line 50, in <module> from psycopg2._psycopg import BINARY, NUMBER, STRING, DATETIME, ROWID ImportError: datetime initialization failed [root@rhevm2017 gregs]# pwd /home/gregs [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# cd [root@rhevm2017 ~]# pwd /root [root@rhevm2017 ~]# python -c 'import datetime' [root@rhevm2017 ~]# python -c 'import psycopg2' [root@rhevm2017 ~]#
Greg, could you please list the content of /home/gregs ?
I am a total dork! Logs and temporary stuff mostly. And some experiments. I wonder what that datetime.py routine does? [root@rhevm2017 ~]# cd /home/gregs [root@rhevm2017 gregs]# ls -al total 13556 drwx------. 2 gregs gregs 4096 Oct 17 08:54 . drwxr-xr-x. 3 root root 18 May 25 2015 .. -rw-r--r--. 1 root root 13761238 Oct 17 00:20 backup.bck -rw-r--r--. 1 root root 3512 Sep 13 14:00 backuplog.log -rw-r--r--. 1 gregs gregs 18 Jan 11 2015 .bash_logout -rw-r--r--. 1 gregs gregs 193 Jan 11 2015 .bash_profile -rw-r--r--. 1 gregs gregs 231 Jan 11 2015 .bashrc -rwxr-xr-x. 1 root root 1020 Sep 13 13:58 createvm-binary.py -rwxr-xr-x. 1 root root 993 Sep 13 13:58 createvm-original.py -rwxr-xr-x. 1 root root 975 Sep 13 13:58 createvm.py -rwxr-xr-x. 1 root root 83 Sep 13 13:58 datetime.py -rw-r--r--. 1 root root 191 Sep 15 11:00 datetime.pyc -rwxr-xr-x. 1 root root 1069 Sep 13 13:58 fire-up-iostat.sh -rw-r--r--. 1 root root 77 Sep 13 13:58 import.py -rwxr-xr-x. 1 root root 408 Sep 13 13:58 listdc.py -rwxr-xr-x. 1 root root 130 Sep 13 13:58 printit.py -rwxr-xr-x. 1 root root 545 Sep 13 13:58 processes.sh -rw-r--r--. 1 root root 4242 Sep 15 09:30 restore20160915.log -rw-r--r--. 1 root root 1189 Oct 17 00:17 restore20161016b.log -rw-r--r--. 1 root root 1189 Oct 17 00:20 restore20161016c.log -rw-r--r--. 1 root root 1189 Oct 16 23:45 restore20161016.log -rw-r--r--. 1 root root 1189 Oct 17 08:54 restore2016-1017e.log -rw-r--r--. 1 root root 1189 Oct 17 00:42 restore20161017.log -rw-r--r--. 1 root root 1189 Sep 14 10:19 restoreconsole.log -rwxr-xr-x. 1 root root 280 Sep 13 13:58 seconds.sh -rwxr-xr-x. 1 root root 639 Sep 13 13:58 setWAD.py -rwxr-xr-x. 1 root root 3663 Sep 13 13:58 stresstest1.py -rwxr-xr-x. 1 root root 3986 Sep 13 13:58 stresstest.py -rw-r--r--. 1 root root 676 Sep 13 13:59 stresstest.rhevm -rwxr-xr-x. 1 root root 1320 Sep 13 13:58 stresstest.sh [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# more datetime.py #!/usr/bin/python import time print "Current date and time " + time.strftime("%c") [root@rhevm2017 gregs]# No way - did I really stumble across a conflict because I don't know my butt from a hole in the ground with python? [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# mv datetime.py greg-datetime.py [root@rhevm2017 gregs]# mv datetime.pyc greg-datetime.pyc [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# python -c 'import psycopg2' [root@rhevm2017 gregs]# [root@rhevm2017 gregs]# engine-backup --mode=restore --file=backup.bck --log=restore2016-1017f.log --provision-db --provision-dwh-db --no-restore-permissions Preparing to restore: - Unpacking file 'backup.bck' ------------------------------------------------------------------------------ Please note: A Reports dump was found inside the backup. This version does not support Reports, and the dump and configuration files will not be restored. ------------------------------------------------------------------------------ Restoring: - Files ------------------------------------------------------------------------------ Please note: Operating system is different from the one used during backup. Current operating system: redhat7 Operating system at backup: redhat6 Apache httpd configuration will not be restored. You will be asked about it on the next engine-setup run. ------------------------------------------------------------------------------ Provisioning PostgreSQL users/databases: - user 'engine', database 'engine' - user 'ovirt_engine_history', database 'ovirt_engine_history' Restoring: - Engine database 'engine' - Cleaning up temporary tables in engine database 'engine' - Resetting DwhCurrentlyRunning in dwh_history_timekeeping in engine database ------------------------------------------------------------------------------ Please note: The engine database was backed up at 2016-10-17 00:19:49.000000000 -0500 . Objects that were added, removed or changed after this date, such as virtual machines, disks, etc., are missing in the engine, and will probably require recovery or recreation. ------------------------------------------------------------------------------ - DWH database 'ovirt_engine_history' You should now run engine-setup. Done. [root@rhevm2017 gregs]# Chalk it up to Greg's learning curve. I'll update the other bz too.
(In reply to Greg Scott from comment #4) > I am a total dork! > > Logs and temporary stuff mostly. And some experiments. I wonder what that > datetime.py routine does? > > [root@rhevm2017 ~]# cd /home/gregs > [root@rhevm2017 gregs]# ls -al > total 13556 > drwx------. 2 gregs gregs 4096 Oct 17 08:54 . > drwxr-xr-x. 3 root root 18 May 25 2015 .. > -rw-r--r--. 1 root root 13761238 Oct 17 00:20 backup.bck > -rw-r--r--. 1 root root 3512 Sep 13 14:00 backuplog.log > -rw-r--r--. 1 gregs gregs 18 Jan 11 2015 .bash_logout > -rw-r--r--. 1 gregs gregs 193 Jan 11 2015 .bash_profile > -rw-r--r--. 1 gregs gregs 231 Jan 11 2015 .bashrc > -rwxr-xr-x. 1 root root 1020 Sep 13 13:58 createvm-binary.py > -rwxr-xr-x. 1 root root 993 Sep 13 13:58 createvm-original.py > -rwxr-xr-x. 1 root root 975 Sep 13 13:58 createvm.py > -rwxr-xr-x. 1 root root 83 Sep 13 13:58 datetime.py Yes, the issue was just here ^^^ By default python searches for a module in the current directory before looking into other paths so you basically overwritten the datatime module... :-) https://docs.python.org/2/tutorial/modules.html#the-module-search-path ... > - DWH database 'ovirt_engine_history' > You should now run engine-setup. > Done. > [root@rhevm2017 gregs]#
Thanks everyone for the investigation while I was on PTO :-) However, perhaps we do want to reopen with summary line "ovirt tools should set a safe python path" or something like that. Perhaps it should be a bug on python itself.