Bug 1385462

Summary:	Error restoring from RHEVM 3.6 to RHVM 4.0 during an upgrade
Product:	Red Hat Enterprise Virtualization Manager	Reporter:	Greg Scott <gscott>
Component:	rhevm-dependencies	Assignee:	Sandro Bonazzola <sbonazzo>
Status:	CLOSED NOTABUG	QA Contact:	Pavel Stehlik <pstehlik>
Severity:	high	Docs Contact:
Priority:	high
Version:	4.0.3	CC:	bazulay, didi, dmoessne, gklein, gscott, lsurette, oourfali, Rhev-m-bugs, stirabos, ykaul
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-10-17 16:52:22 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	Integration	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Bug Depends On:	1385463
Bug Blocks:

Description Greg Scott 2016-10-17 05:54:48 UTC

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]#

Comment 1 Simone Tiraboschi 2016-10-17 09:58:24 UTC

On that system, for same reasons,
 import psycopg2
from any python module fails and so our utility.

Not really reproducible.

Comment 2 Greg Scott 2016-10-17 14:05:07 UTC

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 ~]#

Comment 3 Simone Tiraboschi 2016-10-17 14:10:48 UTC

Greg, could you please list the content of /home/gregs ?

Comment 4 Greg Scott 2016-10-17 14:18:07 UTC

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.

Comment 5 Simone Tiraboschi 2016-10-17 16:52:22 UTC

(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]#

Comment 6 Yedidyah Bar David 2016-10-25 07:47:09 UTC

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.