cancel
Showing results for 
Search instead for 
Did you mean: 

nbpem generating too many logs (PemCORBACall::invokeCall............considered for retry(PemCORBAC.)

spider328
Level 4

Hi!

We run space for our /prd/nbu directory and found out that nbpem has been generating too many logs. Upon further examination of the logs, it showed lots of entries with the following line:

12/12/2017 16:53:02.965 [PemCORBACall::invokeCall] (ID:0x7fdd18ccd280) NBProxy::mailClientStatus preCallProcessing requested call to be considered for retry(PemCORBACall.cpp:79)
12/12/2017 16:53:02.965 [PemCORBACall::invokeCall] (ID:0x7fdd88f3a890) NBProxy::mailClientStatus preCallProcessing requested call to be considered for retry(PemCORBACall.cpp:79)
12/12/2017 16:53:02.965 [PemCORBACall::invokeCall] (ID:0x7fdd39b4f6f0) NBProxy::mailClientStatus preCallProcessing requested call to be considered for retry(PemCORBACall.cpp:79)
12/12/2017 16:53:02.965 [PemCORBACall::invokeCall] (ID:0x7fdd82b52690) NBProxy::mailClientStatus preCallProcessing requested call to be considered for retry(PemCORBACall.cpp:79)
12/12/2017 16:53:02.965 [PemCORBACall::invokeCall] (ID:0x7fdd48ecfa30) NBProxy::mailClientStatus preCallProcessing requested call to be considered for retry(PemCORBACall.cpp:79)

Any idea what is causing this issue?

 

 

14 REPLIES 14

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

We see something about mailClientStatus being repeated over and over.

Has anyone perhaps configured 'Client send mail'  or any kind of mail notification in Host Properties? 

Is sendmail working at OS level?

Is nbpem logging set at a very high level?

Maybe good idea to log a Support call with Veritas to do deeper examination of logs. 

Marianne,

Thanks for your feedback. I have opened up a case with our vendor. I will share if they find anything significant with this issue.

 

What was the outcome of this?  We have the same problem.  

Scott_G1
Level 2

For anyone else with this issue, I just got off the phone with support.  It is a known issue with nbpem not honoring a timeout value.  If you have a media server in your database (nbpemcmd -listhosts) that is not accessible, you may run into this issue.  The only feasible workaround at the moment is to delete the nbpem log folder entirely (you will have to stop the services to be able to delete the folder completely).  They know about the issue and are working on it.  If you have a similar issue, make sure you open a case so that it gets added to the priority list.  There is an internal etrack, but I don't have the number for it.

Froeschke
Level 3

We had the same issue about a month back and found the following process had terminated on the master server:

/usr/openv/netbackup/bin/nbproxy dblib nbpem_email

Support had us restart services on the Master and since then no further occurrence.

 

Krutons
Moderator
Moderator
   VIP   

Interesting, we have had a ticket open for the nbpem logging issue for awhile now and the tech just kept to get logs. I'll have to see if he can find the etrack for us. Do you know if it was only invalid media servers in the nbemmcmd -listhosts or could it be other invalid entries?

Anshu_Pathak
Level 5

Following is applicable for all NetBackup unified (VxUL) logs. (nbpem, nbjm, nbrb, nbemm etc.)

If you run into issue where even after setting the logging level to minimum logs are getting generated, you need to focus on two thing. (1) Did you reduce debug level of correct originator ID (OID) "-o". (2) If some process has entered into infinite loop or is just checking all possible options. (3) Corruption in nblog.conf file, vxlogcfg command completes but changes do not get commited to nblog.conf.

Other answers manily cover option# 2 however option# 1 is the easiest.

Steps to follow for option# 1.

Process the logs with "-i <oid>" and "-d all" switch of vxlogview.

vxlogview -p 51216 -i nbpem -d all

7/16/2018 04:55:00.802 [Debug] NB 51216 nbpem 116 PID:2156 TID:1820 File ID:116 [No context] 6 [PemQueueCall::~PemQueueCall] +++ ENTERING +++ : obj = 0000000001064A48 (d:\nb\8.1.1\src\nb\pem2\PemQueueCall.h:190)
7/16/2018 04:55:21.396 [Debug] NB 51216 libraries 137 PID:2156 TID:1800 File ID:116 [No context] 6 [SvcControl] +++ ENTERING +++ : obj = 0000000000000000 (../WinService.cpp:155)

As you can see in above example, items in red are the originator ID for which you need to reduce debug level. Item in green tells you the log file which has this line. Highlighted number shows that debug level at which this log line will be added to logging.

So in above example log snippet is from nbpem logs which are at DebugLevel 6 and libraries logging is also enabled at DebugLevel 6. So in order to disbale logging I will have to reduce nbpem along with libraries DebugLevel.

There is a reason why default DebugLevel is set to 1 and DiagnosticLevel to 6, this setting does not generate too much logs and could provide some pointers during failures.

How to reduce VxUL logging.

vxlogcfg -p 51216 -o <OID> -s DebugLevel=1 -s DiagnosticLevel=6

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Seems @spider328 has not been back since Dec 2017 to look for answers.... 

@Marianne I totally missed that detail Smiley HappySmiley Happy

I hope it will be helpful to others who get to this page through google.

Krutons
Moderator
Moderator
   VIP   

Unfortunately I don't think it's option #1 as you described.

07/31/2018 10:32:11.736 [Diagnostic] NB 51216 nbpem 116 PID:38944 TID:46953261971200 File ID:116 [No context] 1 V-116-319 [PemCORBACall::invokeCall] NBProxy::mailClientStatus CORBA call failed: CORBA exception: TRANSIENT (IDL:omg.org/CORBA/TRANSIENT:1.0) -- system exception, ID 'IDL:omg.org/CORBA/TRANSIENT:1.0'
OMG minor code (2), described as '*unknown description*', completed = NO
07/31/2018 10:33:56.254 [Diagnostic] NB 51216 nbpem 116 PID:38944 TID:46953272477440 File ID:116 [No context] 1 V-116-218 [NBProxy::postCallProcessing] nbproxy (/usr/openv/var/nbproxy_pem_email.ior) has failed, will restart
07/31/2018 10:34:17.046 [Diagnostic] NB 51216 nbpem 116 PID:38944 TID:46953272477440 File ID:116 [No context] 1 V-116-218 [NBProxy::postCallProcessing] nbproxy (/usr/openv/var/nbproxy_pem_email.ior) has failed, will restart
07/31/2018 10:34:17.046 [Debug] NB 51216 libraries 137 PID:38944 TID:46953272477440 File ID:116 [No context] 1 [EndpointSelector_R2::SetEndPointHostname] epsr2: No Endpoint found with host name, All Endpoints are IP addresses(Endpoint_Selector.cpp:2037)

07/31/2018 10:34:17.823 [Debug] NB 51216 libraries 137 PID:38944 TID:46953272477440 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.823 [Debug] NB 51216 libraries 137 PID:38944 TID:46953272477440 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.823 [Debug] NB 51216 libraries 137 PID:38944 TID:46953272477440 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.823 [Debug] NB 51216 libraries 137 PID:38944 TID:46953272477440 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.824 [Debug] NB 51216 libraries 137 PID:38944 TID:46953261971200 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.824 [Debug] NB 51216 libraries 137 PID:38944 TID:46953261971200 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.824 [Debug] NB 51216 libraries 137 PID:38944 TID:46953261971200 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.824 [Debug] NB 51216 libraries 137 PID:38944 TID:46953261971200 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.825 [Debug] NB 51216 libraries 137 PID:38944 TID:46953272477440 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)
07/31/2018 10:34:17.825 [Debug] NB 51216 libraries 137 PID:38944 TID:46953272477440 File ID:116 [No context] 1 [MailboxMsgPort::getData] outbox is now empty(MailboxMsgPort.cpp:98)

 

As you can see, supposdily nbpem is at DebugLevel 1 but this isn't the case.

[root@<master> ~]# vxlogcfg -l -o nbpem -p NB
Configuration settings for originator 116, of product 51,216...
LogDirectory = /usr/openv/logs/nbpem/
DebugLevel = 0
DiagnosticLevel = 6
DynaReloadInSec = 0
LogToStdout = False
LogToStderr = False
LogToOslog = False
RolloverMode = FileSize | LocalTime
LogRecycle = False
MaxLogFileSizeKB = 51200
RolloverPeriodInSeconds = 43200
RolloverAtLocalTime = 0:00
NumberOfLogFiles = 3
OIDNames = nbpem
AppMsgLogging = ON
L10nLib = /usr/openv/lib/libvxexticu
L10nResource = nbpem
L10nResourceDir = /usr/openv/resources
SyslogIdent = VRTS-NB
SyslogOpt = 0
SyslogFacility = LOG_LOCAL5
LogFilePermissions = 664

 

[root@<master> ~]# vxlogcfg -l -o libraries -p NB
Configuration settings for originator 137, of product 51,216...
LogDirectory = /usr/openv/logs/
DebugLevel = 1
DiagnosticLevel = 6
DynaReloadInSec = 0
LogToStdout = False
LogToStderr = False
LogToOslog = False
RolloverMode = FileSize | LocalTime
LogRecycle = False
MaxLogFileSizeKB = 51200
RolloverPeriodInSeconds = 43200
RolloverAtLocalTime = 0:00
NumberOfLogFiles = 3
OIDNames = libraries
AppMsgLogging = ON
L10nLib = /usr/openv/lib/libvxexticu
L10nResource = libraries
L10nResourceDir = /usr/openv/resources
SyslogIdent = VRTS-NB
SyslogOpt = 0
SyslogFacility = LOG_LOCAL5
LogFilePermissions = 664

 

From the nblog.conf

# 116. Policy Execution Manager
116.L10nResource=nbpem
116.OIDNames=nbpem
116.LogDirectory=nbpem
116.DebugLevel=0
116.AppMsgLogging=ON

# 137. Libutil and libmessaging
137.L10nResource=libraries
137.OIDNames=libraries

If nbpem is truly set to DebugLevel =1 , the logs start to fill up around a couple hundred GB a day. 

@Krutons Please open a Veritas support case as this issue is not just about logs but also about something wrong in configruation or environment. If ignored you may face performance issues on master server. There are CORBA connection errors (its a symptom not the problem) which may cause other failures as well.

That said, you can see the DebugLevel is 1 for libraries, if you set it to 0 these lines will not be logged.

vxlogcfg -a -p NB -o 137 -s DebugLevel=0

 

Krutons
Moderator
Moderator
   VIP   

@Anshu_Pathak Thanks, it started after our upgrade from 7.7.3 to 8.1.1, I've had a ticket open with support for over a month. hasn't even been escalated to backline either. So far, haven't seen much performance issues when we have nbpem logging set to 0.

@Krutons It's good to know that there are no performance issues. You have two choices here (1) To set DebugLevel=0 for libraries(OID 137), it will fix the current issue of growth in nbpem log files. (2) To purse the failed activity that is getting reported in nbpem logs. 

Option 1: 

vxlogcfg -a -p NB -o 137 -s DebugLevel=0 -s DiagnosticLevel=6

Option 2: 

Enable (DebugLevel=6 and DiagnosticLevel=6) ace (OID 156) also known as CORBA, libaries (OID 137), nbpem (OID 116), nbproxy (legacy) and bpdbm (legacy) logs. Collect these nbpem, nbproxy and bpdbm logs,  upload it case and ask Veritas tech support engineer to review them and provide RCA.

Its easier to collect muptiple logs using nbcplogs command.

mkdir /tmp/nbcplogs

nbcplogs -d 1d -l nbpem,nbproxy,bpdbm /tmp/nbcplogs

https://www.veritas.com/support/en_US/doc/123533878-127136857-0/v123548411-127136857

 

 

In case anyone else comes across this issue, here is the TechNote with the Etrack number for the affected version:

https://www.veritas.com/support/en_US/article.100044598