IDB Backup Error

Hi community,

I have error while trying to take IDB backup.

Data protector version is A.10.03. I checked omnidb session report. Critical ones are like below.

[Critical] From: OB2BAR_POSTGRES_BAR@nmade01.prod.nm.local "DPIDB"  Time: 5/10/2019 2:00:05 PM

        Putting the Internal Database into the backup mode failed

[Critical] From: BSM@nmade01.prod.nm.local "HP IDB Internal"  Time: 10.05.2019 14:00:41

        None of the Disk Agents completed successfully.

        Session has failed.

Then I checked omniinetpasswd and it seems ok.

C:\Windows\system32>omniinetpasswd -list

                administrator@PROD

What do I need to check for solving that problem? Could you please help about the solution?

Best regards,

Utku

  • Hi ,

    Please share what is added to the recent logs in %DP_SDATA_DIR%\server\db80\pg\pg_log when the IDB backup fails. This should guide us.

    Regards,
    Sebastian Koehler

  • Hi ,

    Please share what is added to the recent logs in %DP_SDATA_DIR%\server\db80\pg\pg_log when the IDB backup fails. This should guide us.

    Regards,
    Sebastian Koehler

  • Hi  ,

    I run the backup again.  But when I want to open the last log, it gave below error message.

    The document "C:\ProgramData\Omniback\server\db80\pg\pg_log\postgresql-2019-05-29_00000.log is in use by another application and cannot be accessed.

    So I checked log history and find below log messages under "C:\ProgramData\OmniBack\server\db80\pg\pg_log" .

    2019-05-20 07:11:30 GMT LOG: database system was shut down at 2019-05-20 07:09:20 GMT
    2019-05-20 07:11:30 GMT LOG: database system is ready to accept connections
    2019-05-20 07:11:30 GMT LOG: autovacuum launcher started
    2019-05-20 07:14:51 GMT LOG: no match in usermap "hpdpidb" for user "hpdp" authenticated as "SYSTEM"
    2019-05-20 07:14:51 GMT FATAL: SSPI authentication failed for user "hpdp"
    2019-05-20 07:16:50 GMT LOG: no match in usermap "hpdpidb" for user "hpdp" authenticated as "SYSTEM"
    2019-05-20 07:16:50 GMT FATAL: SSPI authentication failed for user "hpdp"
    2019-05-20 07:22:10 GMT LOG: received fast shutdown request
    2019-05-20 07:22:10 GMT LOG: aborting any active transactions
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT FATAL: terminating connection due to administrator command
    2019-05-20 07:22:10 GMT LOG: autovacuum launcher shutting down
    2019-05-20 07:22:10 GMT ERROR: canceling statement due to user request
    2019-05-20 07:22:12 GMT LOG: autovacuum launcher shutting down
    2019-05-20 07:22:12 GMT LOG: shutting down
    2019-05-20 07:22:12 GMT LOG: database system is shut down

    Also I run IDB backup with debug mode. You can find error messages about it at below. Maybe they will help to find the problem. The logs belong to "OB2DBG_8068_2019-05-20-18_POSTGRES_BAR_nmade01.prod.nm.local_6316-6104_IDB3" log file under C:\ProgramData\OmniBack\tmp . I searched for the error message "Putting the Internal Database into the backup mode failed" at the log file. Under that error message, there are below logs.

    [100] token [1] = Normal
    [100] token [2] = 5/20/2019 10:28:19 AM
    [100] token [3] = OB2BAR_POSTGRES_BAR
    [100] token [4] = nmade01.prod.nm.local
    [100] token [5] =  Putting the Internal database into the backup mode finished

    [100] token [6] = DPIDB
    [100] *************** SKPrintf [END] ***************
    [ 6] [REPORT 4] in CPostgresCluster::BackupModeStart
    Marked: ("":Line:0 in '')
    Code is:0
    [Normal] From: OB2BAR_POSTGRES_BAR@nmade01.prod.nm.local "DPIDB" Time: 5/20/2019 10:28:19 AM
    Putting the Internal database into the backup mode finished

     

     

    [ 99] 2019-05-20 10:28:19.866 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":1066)
    [ 99] ===>> (2) CPostgresCluster::BackupChangeMode {
    [ 99]

    [ 99] 2019-05-20 10:28:19.866 ("$PATH: integ/postgres/PostgresSQLCommunications.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":89)
    [ 99] ===>> (3) CPostgresSQLCommunications::ExecuteScript {
    [ 99]

    [ 99] 2019-05-20 10:28:19.866 ("$PATH: integ/postgres/common.cpp $ $Rev: 49252 $ $Date:: 2015-08-07 12:44:15 -040":304)
    [ 99] ===>> (4) ParseUsernameDomain {
    [ 99]
    [130] [ParseUsernameDomain] Parsing user string: PROD\administrator
    [130] [ParseUsernameDomain] Parsed username: administrator and domain: PROD

    [ 99] 2019-05-20 10:28:19.866 ("$PATH: integ/postgres/common.cpp $ $Rev: 49252 $ $Date:: 2015-08-07 12:44:15 -040":332)
    [ 99] <<=== (4) } /* ParseUsernameDomain */
    [ 99]

    [ 99] 2019-05-20 10:28:19.866 ("$PATH: integ/postgres/DPTools.cpp $ $Rev: 48268 $ $Date:: 2015-05-15 06:14:59 -040":295)
    [ 99] ===>> (4) CDPTools::GetUserToken {
    [ 99]

    [ 99] 2019-05-20 10:28:19.866 ("/lib/xtra/win32_suid.c $Rev: 55015 $Date:: 2009-09-11 19:11:14 ":43)
    [ 99] ===>> (5) CheckUserInInetConfig {
    [ 99]

    [ 99] 2019-05-20 10:28:19.866 ("/lib/xtra/win32_suid.c $Rev: 55015 $Date:: 2009-09-11 19:11:14 ":71)
    [ 99] <<=== (5) } /* CheckUserInInetConfig */
    [ 99] RetVal: (bool) TRUE
    [ 99]
    [ 10] User logon failed with [1385] Logon failure: the user has not been granted the requested logon type at this computer.

    [ 99] 2019-05-20 10:28:19.882 ("$PATH: integ/postgres/DPTools.cpp $ $Rev: 48268 $ $Date:: 2015-05-15 06:14:59 -040":318)
    [ 99] <<=== (4) } /* CDPTools::GetUserToken */
    [ 99]

    [ 99] 2019-05-20 10:28:19.882 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1113)
    [ 99] ===>> (4) CmnRunScript {
    [ 99] Args: flags:0x0, timeout:0, argc:6, dir:, exe:C:/Program Files/OmniBack/idb/bin/psql
    [ 99]
    [ 30] C:/Program Files/OmniBack/idb/bin/psql
    [ 30] -Uhpdp
    [ 30] -hlocalhost
    [ 30] -p7112
    [ 30] -cselect pg_start_backup('1558337299');
    [ 30] postgres

    [ 99] 2019-05-20 10:28:19.882 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":596)
    [ 99] ===>> (5) CmnCreateProcess {
    [ 99]

    [ 99] 2019-05-20 10:28:19.882 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":437)
    [ 99] ===>> (6) CreateCommandLine {
    [ 99]
    [ 30] [CreateCommandLine] exe:C:\Program Files\OmniBack\idb\bin\psql
    [ 30] [CreateCommandLine] maxCmdLineLen:32767
    [ 30] [CreateCommandLine] Command line:"C:\Program Files\OmniBack\idb\bin\psql" -Uhpdp -hlocalhost -p7112 "-cselect pg_start_backup('1558337299');" postgres

    [ 99] 2019-05-20 10:28:19.882 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":527)
    [ 99] <<=== (6) } /* CreateCommandLine */
    [ 99] RetVal: (ptr) 00000000009CEC90
    [ 99]
    [199] [CmnCreateProcess] waitForInit:false, foreign:true
    [ 30] [CmnCreateProcess] Process started. pid:6736, tid:2112, handle:00000000000001C0

    [ 99] 2019-05-20 10:28:19.882 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":796)
    [ 99] <<=== (5) } /* CmnCreateProcess */
    [ 99] RetVal: (int) 0
    [ 99]
    [199] [CmnRunScript] read output

    [299] 2019-05-20 10:28:19.882 ("/lib/cmn/common.c $Rev: 62203 $ $Date:: 2018-03-21 04:32:59 ":2844)
    [299] ===>> (5) CmnRunReadLine {
    [299]

    [299] 2019-05-20 10:28:19.882 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1039)
    [299] ===>> (6) CmnPipeRead {
    [299]

    [299] 2019-05-20 10:28:19.882 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":930)
    [299] ===>> (7) Win32_TimedReadEx {
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":993)
    [299] <<=== (7) } /* Win32_TimedReadEx */
    [299] RetVal: (int) 56
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1070)
    [299] <<=== (6) } /* CmnPipeRead */
    [299] RetVal: (int) 56
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1039)
    [299] ===>> (6) CmnPipeRead {
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":930)
    [299] ===>> (7) Win32_TimedReadEx {
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":993)
    [299] <<=== (7) } /* Win32_TimedReadEx */
    [299] RetVal: (int) 2
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1070)
    [299] <<=== (6) } /* CmnPipeRead */
    [299] RetVal: (int) 2
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/common.c $Rev: 62203 $ $Date:: 2018-03-21 04:32:59 ":2892)
    [299] <<=== (5) } /* CmnRunReadLine */
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/common.c $Rev: 62203 $ $Date:: 2018-03-21 04:32:59 ":2844)
    [299] ===>> (5) CmnRunReadLine {
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1039)
    [299] ===>> (6) CmnPipeRead {
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":930)
    [299] ===>> (7) Win32_TimedReadEx {
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":983)
    [299] <<=== (7) } /* Win32_TimedReadEx */
    [299] RetVal: WIN32_PIPE_END
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":881)
    [299] ===>> (7) CmnPipeReadEnd {
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":885)
    [299] <<=== (7) } /* CmnPipeReadEnd */
    [299] RetVal: (int) 0
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1064)
    [299] <<=== (6) } /* CmnPipeRead */
    [299] RetVal: (int) 0
    [299]

    [299] 2019-05-20 10:28:19.929 ("/lib/cmn/common.c $Rev: 62203 $ $Date:: 2018-03-21 04:32:59 ":2923)
    [299] <<=== (5) } /* CmnRunReadLine */
    [299] RetVal: (str) <null>
    [299]

    [ 99] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":312)
    [ 99] ===>> (5) CmnRunExit {
    [ 99]
    [160] [CmnRunExit] elapsed:0.05 user:0.00% system:33.31%
    [160] [CmnRunExit] read:0, write:58, other:1010
    [160] [CmnRunExit] exitcode:2

    [ 99] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":341)
    [ 99] <<=== (5) } /* CmnRunExit */
    [ 99]
    [ 10] [CmnRunScript] Exiting (retval=0, exitcode=0x2)

    [ 99] 2019-05-20 10:28:19.929 ("/lib/cmn/win32exe.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":1286)
    [ 99] <<=== (4) } /* CmnRunScript */
    [ 99] RetVal: (int) 0
    [ 99]
    [ 30] [CPostgresSQLCommunications::ExecuteScript] result = 0, retVal = 2, response=
    -----
    psql: FATAL: SSPI authentication failed for user "hpdp"

    -----


    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresSQLCommunications.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":173)
    [ 99] ===>> (4) CPostgresSQLCommunications::ReadRecord {
    [ 99]

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresSQLCommunications.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":246)
    [ 99] <<=== (4) } /* CPostgresSQLCommunications::ReadRecord */
    [ 99]

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresSQLCommunications.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":131)
    [ 99] <<=== (3) } /* CPostgresSQLCommunications::ExecuteScript */
    [ 99] RetVal: 2
    [ 99]

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":242)
    [ 99] ===>> (3) CPostgresCluster::ResponseCheckFor {
    [ 99]
    [ 30] [CPostgresCluster::ResponseCheckFor] regex search for : pg_start_backup in the : psql: FATAL: SSPI authentication failed for user "hpdp" resulted in : 0

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":253)
    [ 99] <<=== (3) } /* CPostgresCluster::ResponseCheckFor */
    [ 99] RetVal: (bool) FALSE
    [ 99]

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":242)
    [ 99] ===>> (3) CPostgresCluster::ResponseCheckFor {
    [ 99]
    [ 30] [CPostgresCluster::ResponseCheckFor] regex search for : pg_start_backup in the : resulted in : 0

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":253)
    [ 99] <<=== (3) } /* CPostgresCluster::ResponseCheckFor */
    [ 99] RetVal: (bool) FALSE
    [ 99]
    [ 30] [CPostgresCluster::BackupChangeMode] Error in output after BackupChangeMode, unexpected table contents
    [ 30] [VarDbgDump] 000000000013C128
    (('psql: FATAL: SSPI authentication failed for user &#1;Qhpdp&#1;Q'))

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":242)
    [ 99] ===>> (3) CPostgresCluster::ResponseCheckFor {
    [ 99]
    [ 30] [CPostgresCluster::ResponseCheckFor] regex search for : ERROR: a backup is already in progress in the : psql: FATAL: SSPI authentication failed for user "hpdp" resulted in : 0

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":253)
    [ 99] <<=== (3) } /* CPostgresCluster::ResponseCheckFor */
    [ 99] RetVal: (bool) FALSE
    [ 99]

    [ 99] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":1095)
    [ 99] <<=== (2) } /* CPostgresCluster::BackupChangeMode */
    [ 99]
    [100] *************** NlsPackMessage [START] ***************
    [100] Message [175:105]
    [100] Let's collect data from stack ...
    [100] Returned message (RetVal): ?15&#3; &#7;&#1;[175:105]&#3;

    [100] *************** NlsPackMessage [END] ***************
    [ 30] [exception] message: ?15&#3; &#7;&#1;[175:105]&#3;
    [ 30] [exception] details: Unexpected table content

    [ -1] 2019-05-20 10:28:19.929 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":1095)
    [CPostgresCluster::BackupChangeMode] Exception: ?15&#3; &#7;&#1;[175:105]&#3;
    Details: Unexpected table content

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresAgent.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":1129)
    [ 99] Unwinding DbgStack to level 0:
    [ 99] <<=== (1) } /* CPostgresCluster::BackupModeStart */
    [ 30] [CPostgresAgent::PerformBackup] Exception caught : ?15&#3; &#7;&#1;[175:105]&#3;, details: Unexpected table content

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresAgent.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":3028)
    [ 99] ===>> (1) CPostgresAgent::FinalizeStreams {
    [ 99]
    [ 31] streams already finalized

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresAgent.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":3055)
    [ 99] <<=== (1) } /* CPostgresAgent::FinalizeStreams */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2backup.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":829)
    [ 99] ===>> (1) OB2_EndBackup {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2common.c $Rev: 59324 $ $Date:: 2017-07-28 10:31:48 ":704)
    [ 99] ===>> (2) OB2_Stop {
    [ 99]
    [ 18] [EnvReadInt] OB2RECONNECT_RETRY=n/a (default:0)

    [112] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":6937)
    [112] ===>> (3) ipc_sendDataEx {
    [112] Args: handle=2, buffer size=8, timeout=0
    [112]

    [112] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":6790)
    [112] ===>> (4) ipcI_sendPacket {
    [112] Args: size:12, timeout:0
    [112]
    [112] [IpcIO_Send] (2 408 000000000115E3AC 12) [PLAIN]
    [270] [DbgDumpMem] 12/256 bytes SEND DATA :
    [270] 00 00 00 08 FF FE 36 00 00 00 00 00 ......6.....
    [260] [IpcIO_Send] ret=12
    [112] [ipcI_sendPacket] bytes_sent=12

    [112] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":6906)
    [112] <<=== (4) } /* ipcI_sendPacket */
    [112] RetVal: (int) 12
    [112]

    [112] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":7026)
    [112] <<=== (3) } /* ipc_sendDataEx */
    [112] RetVal: (int) 12
    [112]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2common.c $Rev: 59324 $ $Date:: 2017-07-28 10:31:48 ":299)
    [ 99] ===>> (3) OB2_CloseSession {
    [ 99] Args: smHandle:2
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2common.c $Rev: 59324 $ $Date:: 2017-07-28 10:31:48 ":344)
    [ 99] ===>> (4) OB2_InitCsa {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2common.c $Rev: 59324 $ $Date:: 2017-07-28 10:31:48 ":351)
    [ 99] <<=== (4) } /* OB2_InitCsa */
    [ 99] RetVal: (int) 0
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":1924)
    [ 99] ===>> (4) MCsaDisconnectSession {
    [ 99]
    [ 18] [EnvReadInt] OB2SHUTDOWNTIMEOUT=n/a (default:60)

    [ 60] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5559)
    [ 60] ===>> (5) IpcShutdownAndCloseConnectionEx {
    [ 60] Args: handle:2, flags:2, timeout:60
    [ 60]

    [ 60] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5451)
    [ 60] ===>> (6) IpcShutdownAndDiscard {
    [ 60] Args: handle:2, mode:2, timeout:60
    [ 60]
    [112] [IpcShutdownAndDiscard] shutdown(408, 2)

    [ 60] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5521)
    [ 60] <<=== (6) } /* IpcShutdownAndDiscard */
    [ 60] RetVal: (int) 0
    [ 60]

    [112] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5594)
    [112] [IpcShutdownAndCloseConnectionEx] handle:2. closed socket 408

    [ 30] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":1399)
    [112] [IpcSetEvent] handle:2 event:IPC_NO_EVENT
    [112] [IpcSetRcvSize] IpcEntryFreePeekData:553 handle:2 oldsize:0 size:0
    [ 66] [IpcEntryRelease] 2 (2,65536)

    [ 60] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5606)
    [ 60] <<=== (5) } /* IpcShutdownAndCloseConnectionEx */
    [ 60] RetVal: (int) 0
    [ 60]

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":1960)
    [ 99] <<=== (4) } /* MCsaDisconnectSession */
    [ 99] RetVal: (int) 0
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":93)
    [ 99] ===>> (4) CsaPtdDestroy {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5426)
    [ 99] ===>> (5) IpcCloseConnection {
    [ 99] Args: handle:1
    [ 99]
    [199] [IpcCloseAt] sock:352

    [112] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5367)
    [112] [IpcCloseAt] handle:1. closed socket 352
    [112] [IpcSetRcvSize] IpcEntryFreePeekData:553 handle:1 oldsize:0 size:0

    [ 30] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":1399)
    [112] [IpcSetEvent] handle:1 event:IPC_NO_EVENT
    [112] [IpcSetRcvSize] IpcEntryFreePeekData:553 handle:1 oldsize:0 size:0
    [ 66] [IpcEntryRelease] 1 (1,65536)

    [ 99] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":5436)
    [ 99] <<=== (5) } /* IpcCloseConnection */
    [ 99] RetVal: (int) 0
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":125)
    [ 99] <<=== (4) } /* CsaPtdDestroy */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2common.c $Rev: 59324 $ $Date:: 2017-07-28 10:31:48 ":323)
    [ 99] <<=== (3) } /* OB2_CloseSession */
    [ 99] RetVal: (int) 0
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2common.c $Rev: 59324 $ $Date:: 2017-07-28 10:31:48 ":723)
    [ 99] <<=== (2) } /* OB2_Stop */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2backup.c $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 ":845)
    [ 99] <<=== (1) } /* OB2_EndBackup */
    [ 99] RetVal: (int) 0
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresAgent.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":1155)
    [ 99] <<=== (0) } /* CPostgresAgent::PerformBackup */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresAgent.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":62)
    [ 99] ===>> (0) CPostgresAgent::~CPostgresAgent {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":58)
    [ 99] ===>> (1) CPostgresCluster::~CPostgresCluster {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresCluster.cpp $ $Rev: 55015 $ $Date:: 2016-10-06 07:01:23 -040":62)
    [ 99] <<=== (1) } /* CPostgresCluster::~CPostgresCluster */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("$PATH: integ/postgres/PostgresAgent.cpp $ $Rev: 61652 $ $Date:: 2018-01-30 15:09:18 -050":74)
    [ 99] <<=== (0) } /* CPostgresAgent::~CPostgresAgent */
    [ 99]
    [100] *************** NlsPackMessage [START] ***************
    [100] Message [12:1]
    [100] Let's collect data from stack ...
    [100] Simple message = &#7;&#2;[2003]
    [100] Simple message = &#7;&#5;1558337299
    [100] Simple message = OB2BAR_POSTGRES_BAR
    [100] Simple message = nmade01.prod.nm.local
    [100] buf[nested] = ?15&#3; &#7;&#1;[175:105]&#3;
    [100] Simple message = DPIDB
    [100] Returned message (RetVal): ?15&#3; &#7;&#1;[12:1]&#3; &#7;&#2;[2003]&#3; &#7;&#5;1558337299&#3; OB2BAR_POSTGRES_BAR&#3; nmade01.prod.nm.local&#3; &#7;&#1;[175:105]&#3; DPIDB&#3;

    [100] *************** NlsPackMessage [END] ***************

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2service.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":890)
    [ 99] ===>> (0) BAR2ReportHook {
    [ 99]
    [100] *************** SKPrintf [START] ***************
    [100] Tokenize the string...
    [100] token [0] = &#7;[%1] From: %3@%4 "%6" Time: %2
    %5

    [100] token [1] = Critical
    [100] token [2] = 5/20/2019 10:28:19 AM
    [100] token [3] = OB2BAR_POSTGRES_BAR
    [100] token [4] = nmade01.prod.nm.local
    [100] token [5] = &#7; Putting the Internal Database into the backup mode failed

    [100] token [6] = DPIDB
    [100] *************** SKPrintf [END] ***************
    [ 18] [EnvReadInt] OB2_CLI_UTF8=n/a (default:0)

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2service.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":946)
    [ 99] <<=== (0) } /* BAR2ReportHook */
    [ 99] RetVal: (int) 0
    [ 99]

    [ 5] 2019-05-20 10:28:19.945 ("integ/postgres/postgres_bar.cpp $ $Rev: 44590 $ $Date:: 2014-10-02 03:07:15 -040":114)
    [100] *************** SKPrintf [START] ***************
    [100] Tokenize the string...
    [100] token [0] = &#7; Putting the Internal Database into the backup mode failed

    [100] *************** SKPrintf [END] ***************
    [ 5] [REPORT 3] in POSTGRES_BAR:main
    Marked: ("":Line:0 in '')
    Code is:0
    Putting the Internal Database into the backup mode failed

     


    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2service.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":615)
    [ 99] ===>> (0) OB2_Exit {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":93)
    [ 99] ===>> (1) CsaPtdDestroy {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":96)
    [ 99] <<=== (1) } /* CsaPtdDestroy */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":2348)
    [ 99] ===>> (1) IpcExit {
    [ 99]
    ============== IPC Statistics (pid=6316,tid=6104) ===================
    recv.count:10, recv.nblocked:0, send.count:13, send.nblocked:0

    [ 99] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":2180)
    [ 99] ===>> (2) SecExit {
    [ 99] Args: atExit=0
    [ 99]
    [ 30] [SecExit] Unloading shared libs ...

    [ 99] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":2212)
    [ 99] <<=== (2) } /* SecExit */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/lib/ipc/ipc.c $Rev: 62216 $ $Date:: 2018-03-21 10:24:56 ":2400)
    [ 99] <<=== (1) } /* IpcExit */
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/integ/bar2/ob2service.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":697)
    [ 99] <<=== (0) } /* OB2_Exit */
    [ 99] RetVal: (int) 0
    [ 99]

    [ 1] 2019-05-20 10:28:19.945 ("/lib/cmn/common.c $Rev: 62203 $ $Date:: 2018-03-21 04:32:59 ":624)
    [ 1] CmnExit(cmnUsageCount:1)

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":93)
    [ 99] ===>> (0) CsaPtdDestroy {
    [ 99]

    [ 99] 2019-05-20 10:28:19.945 ("/cs/csa/mcsa.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":96)
    [ 99] <<=== (0) } /* CsaPtdDestroy */
    [ 99]

    [199] 2019-05-20 10:28:19.945 ("/lib/cmn/debug.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":474)
    [199] Function trace (currentLevel=-1):
    [199]
    [DbgDumpProcMetrics] elapsed:2.095 user:8.948% system:3.729%
    [DbgDumpProcMetrics] read:137607, write:312309, other:233556
    [DbgDumpProcMetrics] PeakWorkingSetSize:11028, WorkingSetSize:9284, QuotaPeakPagedPoolUsage:163, QuotaPagedPoolUsage:133, QuotaPeakNonPagedPoolUsage:12, QuotaNonPagedPoolUsage:9, PagefileUsage:6628, PeakPagefileUsage:8036, PrivateUsage:6628
    [safemem_trace_dump] malloc:1274, calloc:9, realloc:81, free:1274

    [ -1] 2019-05-20 10:28:19.945 ("/lib/cmn/debug.c $Rev: 62033 $ $Date:: 2018-03-06 09:55:27 ":479)
    ==================================================================
    DEBUGGING ENDED PROPERLY
    ==================================================================

     

  • Hi ,


     wrote:

    I run the backup again.  But when I want to open the last log, it gave below error message.

    The document "C:\ProgramData\Omniback\server\db80\pg\pg_log\postgresql-2019-05-29_00000.log is in use by another application and cannot be accessed.


    Open it with the Windows editor (Notepad) or copy it to a different place first. It should have all the information we need to fix this.

    Regards,
    Sebastian Koehler

  • Hi  ,

    The last log message are as below.

    2019-05-29 10:20:37 GMT LOG: no match in usermap "hpdpidb" for user "hpdp" authenticated as "SYSTEM"
    2019-05-29 10:20:37 GMT FATAL: SSPI authentication failed for user "hpdp"
    2019-05-29 12:01:47 GMT LOG: no match in usermap "hpdpidb" for user "hpdp" authenticated as "SYSTEM"
    2019-05-29 12:01:47 GMT FATAL: SSPI authentication failed for user "hpdp"

     

  • Hello ,

    Have you changed the Data Protector services from administrator@PROD to LOCAL SYSTEM?

    Regards,
    Sebastian Koehler

  • Hi  ,

    Actually I didn't do the configuration at this server.  But as I understand, it arranged to administrator@PROD. I checked below parameter.

    C:\Windows\system32>omniinetpasswd -list

                    administrator@PROD

    At above, do I  need to see the result as LOCAL SYSTEM? Do I need to change it to LOCAL SYSTEM? Could you please share how can I change it? 

     

  • Verified Answer

    Hello ,

    You need to check the Windows Service configuration for the Data Protector services. Make sure Application Server, CRS, IDB and IDB connection pooler are not running as LOCAL SYSTEM. It should be a user with local Administrator rights. The user administrator@PROD is not perfect, but should do the job and then we can consider changing it properly to a dedicated service account later.

    If the services are already configured to use administrator@PROD then run omniinetpasswd -clean and omniinetpasswd -add administrator@PROD from an elevated command prompt to re-add it. 

    2019-05-29_17h57_17.png

    Regards,
    Sebastian Koehler

  • Hi  ,

    Thanks a lot for your answers. The problem solved with your solution. I changed the service users as PROD\Administrator and it started to take IDB backup.

    Again thanks a lot. Have a good day.

    Best regards,

    Utku